Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
jpmeijers opened this issue Nov 8, 2020 · 4 comments
Open

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

jpmeijers opened this issue Nov 8, 2020 · 4 comments

Comments

@jpmeijers
Copy link

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.
@jpmeijers jpmeijers mentioned this issue Nov 19, 2020
Open
@c4tghs
Copy link

c4tghs commented Apr 16, 2023

@jpmeijers Did you find a solution for this issue?

@jpmeijers
Copy link
Author

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. mcci-catena/arduino-lmic#827 (comment)

@c4tghs
Copy link

c4tghs commented Apr 18, 2023

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jpmeijers @c4tghs