basicmac Question: OTAA join only succeeds on 3rd try

I see the following in the TTN console, using the OTAA example. This tells me that the OTAA join only succeeds at the 3rd try.

The debug log looks like this:

23:07:16.956 -> 
23:07:16.956 -> 
23:07:16.956 -> Starting
23:07:16.956 -> 
23:07:16.990 -> 863: EV_JOINING
23:07:16.990 -> 00:00:00.014: engineUpdate[opmode=0x4]
23:07:20.176 -> 00:00:03.194: engineUpdate[opmode=0x4]
23:07:20.209 -> 200392: EV_TXSTART
23:07:20.209 -> 00:00:03.207: engineUpdate[opmode=0x884]
23:07:20.209 -> 00:00:03.210: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.1,pow=16,len=23]: 00A59401D07ED5B37068A62E526F9BDA00F8EB58719C48
23:07:20.276 -> 205428: EV_TXDONE
23:07:20.276 -> 00:00:03.287: engineUpdate[opmode=0x884]
23:07:25.288 -> 00:00:08.283: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.1,rxtime=517904]
23:07:25.288 -> 00:00:08.291: WARNING: rxtime is 302 ticks in the past! (ramp-up time 1 ms / 103 ticks)
23:07:25.288 -> 00:00:08.299: RX: TIMEOUT (11019 us)
23:07:26.317 -> 00:00:09.299: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=581396]
23:07:26.317 -> 00:00:09.307: WARNING: rxtime is 298 ticks in the past! (ramp-up time 1 ms / 110 ticks)
23:07:26.516 -> 00:00:09.537: RX: TIMEOUT (11019 us)
23:07:26.583 -> 00:00:09.588: engineUpdate[opmode=0x4]
23:07:26.583 -> 599988: EV_TXSTART
23:07:26.616 -> 00:00:09.600: engineUpdate[opmode=0x884]
23:07:26.616 -> 00:00:09.603: TX[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.3,pow=16,len=23]: 00A59401D07ED5B37068A62E526F9BDA00057E2BC42AD0
23:07:26.649 -> 605025: EV_TXDONE
23:07:26.649 -> 00:00:09.681: engineUpdate[opmode=0x884]
23:07:31.693 -> 00:00:14.677: RX_MODE[mod=LoRa,sf=7,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.3,rxtime=917501]
23:07:31.693 -> 00:00:14.684: WARNING: rxtime is 303 ticks in the past! (ramp-up time 1 ms / 104 ticks)
23:07:31.693 -> 00:00:14.692: RX: TIMEOUT (11019 us)
23:07:32.689 -> 00:00:15.693: RX_MODE[mod=LoRa,sf=12,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=980993]
23:07:32.689 -> 00:00:15.701: WARNING: rxtime is 287 ticks in the past! (ramp-up time 1 ms / 111 ticks)
23:07:32.921 -> 00:00:15.930: RX: TIMEOUT (11019 us)
23:07:43.386 -> 00:00:26.396: engineUpdate[opmode=0x4]
23:07:43.420 -> 1650630: EV_TXSTART
23:07:43.420 -> 00:00:26.411: engineUpdate[opmode=0x884]
23:07:43.420 -> 00:00:26.413: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=868.5,pow=16,len=23]: 00A59401D07ED5B37068A62E526F9BDA001225F50FCA55
23:07:43.552 -> 1658888: EV_TXDONE
23:07:43.552 -> 00:00:26.543: engineUpdate[opmode=0x884]
23:07:48.564 -> 00:00:31.539: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.5,rxtime=1971395]
23:07:48.564 -> 00:00:31.547: WARNING: rxtime is 306 ticks in the past! (ramp-up time 1 ms / 102 ticks)
23:07:48.696 -> 00:00:31.677: RX[rssi=-36,snr=12.25,len=33]: 20D7BDCA28CA0D50BE0474585A888A0E685498A23BFA74B33DDE0245F382462DF6
23:07:48.729 -> 00:00:31.710: Setup channel[idx=3,freq=867.1]
23:07:48.729 -> 00:00:31.713: Setup channel[idx=4,freq=867.3]
23:07:48.729 -> 00:00:31.717: Setup channel[idx=5,freq=867.5]
23:07:48.729 -> 00:00:31.721: Setup channel[idx=6,freq=867.7]
23:07:48.729 -> 00:00:31.725: Setup channel[idx=7,freq=867.9]
23:07:48.729 -> 1983117: EV_JOINED
23:07:48.729 -> 00:00:31.730: engineUpdate[opmode=0x800]
23:07:48.729 -> 00:00:31.734: engineUpdate[opmode=0x808]
23:07:48.729 -> 1984573: EV_TXSTART
23:07:48.763 -> 00:00:31.754: engineUpdate[opmode=0x888]
23:07:48.763 -> 00:00:31.757: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=0,freq=867.9,pow=16,len=26]: 407F26012680000001923B055101A3BEC810D286BBE75B85BD1B
23:07:48.763 -> Packet queued
23:07:48.895 -> 1992903: EV_TXDONE
23:07:48.895 -> 00:00:31.887: engineUpdate[opmode=0x888]
23:07:49.890 -> 00:00:32.883: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=867.9,rxtime=2055409]
23:07:49.890 -> 00:00:32.891: WARNING: rxtime is 309 ticks in the past! (ramp-up time 1 ms / 104 ticks)
23:07:49.890 -> 00:00:32.906: RX: TIMEOUT (11019 us)
23:07:50.886 -> 00:00:33.884: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=2117973]
23:07:50.886 -> 00:00:33.892: WARNING: rxtime is 298 ticks in the past! (ramp-up time 1 ms / 109 ticks)
23:07:50.919 -> 00:00:33.921: RX: TIMEOUT (11019 us)
23:07:50.919 -> 2121318: EV_TXCOMPLETE (includes waiting for RX windows)
23:07:50.952 -> 00:00:33.942: engineUpdate[opmode=0x800]
23:08:48.761 -> 00:01:31.775: engineUpdate[opmode=0x808]
23:08:48.827 -> 5737046: EV_TXSTART
23:08:48.827 -> 00:01:31.793: engineUpdate[opmode=0x888]
23:08:48.827 -> 00:01:31.796: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=1,freq=868.3,pow=16,len=26]: 407F26012680010001D90C60068B42B4653CB7F3F880E0F6FE01
23:08:48.827 -> Packet queued
23:08:48.926 -> 5745385: EV_TXDONE
23:08:48.926 -> 00:01:31.927: engineUpdate[opmode=0x888]
23:08:49.955 -> 00:01:32.923: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=868.3,rxtime=5807891]
23:08:49.955 -> 00:01:32.931: WARNING: rxtime is 314 ticks in the past! (ramp-up time 1 ms / 104 ticks)
23:08:49.955 -> 00:01:32.946: RX: TIMEOUT (11019 us)
23:08:50.950 -> 00:01:33.924: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=5870455]
23:08:50.950 -> 00:01:33.932: WARNING: rxtime is 314 ticks in the past! (ramp-up time 1 ms / 110 ticks)
23:08:50.950 -> 00:01:33.961: RX: TIMEOUT (11019 us)
23:08:52.510 -> 5970869: EV_TXCOMPLETE (includes waiting for RX windows)
23:08:52.544 -> 00:01:35.535: engineUpdate[opmode=0x800]
23:09:48.793 -> 00:02:31.812: engineUpdate[opmode=0x808]
23:09:48.826 -> 9489368: EV_TXSTART
23:09:48.826 -> 00:02:31.830: engineUpdate[opmode=0x888]
23:09:48.859 -> 00:02:31.833: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=2,freq=867.5,pow=16,len=26]: 407F26012680020001CB0913AFCD89666C572A09ED63758C5A87
23:09:48.859 -> Packet queued
23:09:48.959 -> 9497706: EV_TXDONE
23:09:48.959 -> 00:02:31.964: engineUpdate[opmode=0x888]
23:09:49.987 -> 00:02:32.960: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=867.5,rxtime=9560212]
23:09:49.987 -> 00:02:32.968: WARNING: rxtime is 313 ticks in the past! (ramp-up time 1 ms / 103 ticks)
23:09:49.987 -> 00:02:32.983: RX: TIMEOUT (11019 us)
23:09:50.982 -> 00:02:33.961: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=9622776]
23:09:50.982 -> 00:02:33.972: WARNING: rxtime is 476 ticks in the past! (ramp-up time 4 ms / 272 ticks)
23:09:50.982 -> 00:02:34.001: RX: TIMEOUT (11019 us)
23:09:52.109 -> 9694604: EV_TXCOMPLETE (includes waiting for RX windows)
23:09:52.109 -> 00:02:35.115: engineUpdate[opmode=0x800]
23:10:48.855 -> 00:03:31.849: engineUpdate[opmode=0x808]
23:10:48.888 -> 13241694: EV_TXSTART
23:10:48.888 -> 00:03:31.868: engineUpdate[opmode=0x888]
23:10:48.888 -> 00:03:31.871: TX[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=0,ih=0,fcnt=3,freq=867.7,pow=16,len=26]: 407F260126800300017268ED6432ABA29939B90A70A96CAA2B78
23:10:48.888 -> Packet queued
23:10:49.021 -> 13250039: EV_TXDONE
23:10:49.021 -> 00:03:32.001: engineUpdate[opmode=0x888]
23:10:50.016 -> 00:03:32.998: RX_MODE[mod=LoRa,sf=8,bw=125,cr=4/5,nocrc=1,ih=0,freq=867.7,rxtime=13312545]
23:10:50.016 -> 00:03:33.005: WARNING: rxtime is 321 ticks in the past! (ramp-up time 1 ms / 104 ticks)
23:10:50.016 -> 00:03:33.020: RX: TIMEOUT (11019 us)
23:10:51.011 -> 00:03:33.998: RX_MODE[mod=LoRa,sf=9,bw=125,cr=4/5,nocrc=1,ih=0,freq=869.5,rxtime=13375109]
23:10:51.011 -> 00:03:34.007: WARNING: rxtime is 314 ticks in the past! (ramp-up time 1 ms / 109 ticks)
23:10:51.044 -> 00:03:34.036: RX: TIMEOUT (11019 us)
23:10:51.077 -> 13380150: EV_TXCOMPLETE (includes waiting for RX windows)
23:10:51.077 -> 00:03:34.084: engineUpdate[opmode=0x800]

Currently I am not adjusting the rx windows (see #23). So maybe the receive windows are just too small and the rx is missed at faster SFs.

Nov 08 '20 21:11 jpmeijers

@jpmeijers Did you find a solution for this issue?

Apr 16 '23 21:04 c4tghs

I haven't tried using basic mac recently. The MCCI LMiC had a similar issue, and there the fix was to increase the receive windows by a couple of percent. https://github.com/mcci-catena/arduino-lmic/issues/827#issuecomment-1162896175

Apr 17 '23 06:04 jpmeijers

I'm getting an error that both MAX_CLOCK_ERROR and LMIC_setClockError are not declared. I found the issue you opened concerning these errors, but they have not been resolved... Unfortunately, I can't use the MCCI LMiC library since I'm using a board with SX1262. Do you maybe have suggestions on a library for the SX1262 chip? Thank you for your response.

Apr 18 '23 19:04 c4tghs

For the sx126x I have used https://github.com/beegee-tokyo/SX126x-Arduino which worked quite well.

I think the only reason for using this Basic Mac repo is that in the future it will have better Lacuna integration.

Apr 19 '23 08:04 jpmeijers