search

LacunaSpace / basicmac

BasicMAC LoRaWAN stack that supports (but is not limited to) Arduino
Other
76 stars 18 forks source link

Question: OTAA join only succeeds on 3rd try #24

Open jpmeijers opened 3 years ago

jpmeijers commented 3 years ago

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.

image

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.

c4tghs commented 1 year ago

@jpmeijers Did you find a solution for this issue?

jpmeijers commented 1 year ago

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

c4tghs commented 1 year ago

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.

jpmeijers commented 1 year ago

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.