LoRaWAN Datarate with ADR (v 6.5.0) #1040

michapr · 2024-03-29T19:39:26Z

michapr
Mar 29, 2024

Hi,

I'm using for test the "LoRaWAN_Reference.ino" with the only modification node.setADR(true);

After the Heltec WSL stick is connecting to TTN always the SF10BW125 will be used.

Before with the previous version all was fine, SF7BW125 was used by default.
(Also made a downgrade and tested again)

With second device (higher RSSI value) the same...

If I disable ADR and set the datarate to node.setDatarate(5); the SF7BW125 will be used.

What can be wrong here?

THANKS!

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x28 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x43c
load:0x403c9700,len:0xbec
load:0x403cc700,len:0x2a3c
SHA-256 comparison failed:
Calculated: dcde8d8a4817d9bf5d5d69a7247667264e4e10ac7493514868b61f5aa6146539
Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
Attempting to boot anyway...
entry 0x403c98d8

Setup
Initalise the radio
RLB_DBG: RadioLib Debug Info
RLB_DBG: Version:  6.5.0.0
RLB_DBG: Platform: ESP32
RLB_DBG: Compiled: Mar 29 2024 18:40:51

RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
RLB_DBG: 0000320 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 | SX1261 V2D 2D02.
RLB_DBG:
RLB_DBG: M      SX126x
Join ('login') to the LoRaWAN Network
RLB_PRO: Configuration mismatch (checksum: 0, mode: 0, class: 0, plan: 1)
RLB_PRO: Nonces buffer:
RLB_PRO: 0000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ................
RLB_PRO: Clearing buffer and starting fresh
RLB_PRO: Setting up dynamic channels
RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
RLB_PRO: [MAC] 0x03
RLB_PRO: 0000000 20 00 00 80                                     |  ...
RLB_PRO: LinkADRReq: dataRate = 2, txPower = 0, chMask = 0x0000, chMaskCntl = 0, nbTrans = 0
RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
RLB_PRO: PHY: TX = 16 dBm
RLB_PRO: LinkADRAns: status = 0x07
RLB_PRO: [MAC] 0x04
RLB_PRO: 0000000 07                                              | .
RLB_PRO: DutyCycleReq: max duty cycle = 1/2^7
RLB_PRO: [MAC] 0x05
RLB_PRO: 0000000 00 d2 ad 84                                     | ....
RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 0, freq = 869.525024
RLB_PRO: RXParamSetupAns: status = 0x07
RLB_PRO: [MAC] 0x08
RLB_PRO: 0000000 01                                              | .
RLB_PRO: RXTimingSetupReq: delay = 1 sec
RLB_PRO: [MAC] 0x09
RLB_PRO: 0000000 05                                              | .
RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 0, maxEirp = 16 dBm
RLB_PRO: [MAC] 0x0C
RLB_PRO: 0000000 65                                              | e
RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
RLB_PRO: [MAC] 0x0F
RLB_PRO: 0000000 fa                                              | .
RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
RLB_PRO: RejoinParamSetupAns: status = 0x03
RLB_PRO:
RLB_PRO: PHY: Frequency UL = 868.100 MHz
RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
RLB_DBG: Timeout in 1853 ms
RLB_PRO: Join-request sent <-- Rx Delay start
RLB_PRO:
RLB_PRO: PHY: Frequency DL = 868.100 MHz
RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end
RLB_PRO: Closing Rx1 window
RLB_PRO: joinAcceptMsg:
RLB_PRO: 0000000 20 0f 00 00 13 00 00 b8 e2 0b 26 83 05 18 4f 84 |  .........&...O.
RLB_PRO: 0000010 e8 56 84 b8 5e 84 88 66 84 58 6e 84 00 e2 06 db | .V..^..f.Xn.....
RLB_PRO: 0000020 7f                                              | .
RLB_PRO: JoinNoncePrev: 0, JoinNonce: 15
RLB_PRO: LoRaWAN revision: 1.1
RLB_PRO: [MAC] 0x05
RLB_PRO: 0000000 03 d2 ad 84                                     | ....
RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 3, freq = 869.525024
RLB_PRO: RXParamSetupAns: status = 0x07
RLB_PRO: [MAC] 0x08
RLB_PRO: 0000000 05                                              | .
RLB_PRO: RXTimingSetupReq: delay = 5 sec
RLB_PRO: Setting up dynamic channels
RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
RLB_PRO: Processing CFList
RLB_PRO: [MAC] 0x07
RLB_PRO: 0000000 03 18 4f 84 50                                  | ..O.P
RLB_PRO: NewChannelReq:
RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
RLB_PRO: NewChannelAns: status = 0x03
RLB_PRO: [MAC] 0x07
RLB_PRO: 0000000 04 e8 56 84 50                                  | ..V.P
RLB_PRO: NewChannelReq:
RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
RLB_PRO: NewChannelAns: status = 0x03
RLB_PRO: [MAC] 0x07
RLB_PRO: 0000000 05 b8 5e 84 50                                  | ..^.P
RLB_PRO: NewChannelReq:
RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
RLB_PRO: NewChannelAns: status = 0x03
RLB_PRO: [MAC] 0x07
RLB_PRO: 0000000 06 88 66 84 50                                  | ..f.P
RLB_PRO: NewChannelReq:
RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
RLB_PRO: NewChannelAns: status = 0x03
RLB_PRO: [MAC] 0x07
RLB_PRO: 0000000 07 58 6e 84 50                                  | .Xn.P
RLB_PRO: NewChannelReq:
RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
RLB_PRO: NewChannelAns: status = 0x03
[LoRaWAN] DevAddr: 260BE2B8
Ready!

[LoRaWAN] Requesting LinkCheck and DeviceTime
RLB_PRO:
RLB_PRO: PHY: Frequency UL = 867.500 MHz
RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
RLB_PRO: Uplink MAC payload (3 commands):
RLB_PRO: 0000000 0b 01 02 0d                                     | ....
RLB_PRO: Uplink (FcntUp = 0) decoded:
RLB_PRO: 0000000 c0 00 78 56 5c 3e ce 3f 13 00 00 00 34 12 ba ab | ..xV\>.?....4...
RLB_PRO: 0000010 80 b8 e2 0b 26 84 00 00 3f ef 29 bf 0a 7d 4e 69 | ....&...?.)..}Ni
RLB_PRO: 0000020 14 00 ce 3f                                     | ...?
RLB_DBG: Timeout in 1853 ms
RLB_PRO: Uplink sent <-- Rx Delay start
RLB_PRO:
RLB_PRO: PHY: Frequency DL = 867.500 MHz
RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end
RLB_PRO: Closing Rx1 window
RLB_PRO: Downlink (NFcntDown = 0) encoded:
RLB_PRO: 0000000 49 00 00 00 00 01 b8 e2 0b 26 00 00 00 00 00 19 | I........&......
RLB_PRO: 0000010 60 b8 e2 0b 26 a0 00 00 00 18 e9 89 12 b3 0e 9b | `...&...........
RLB_PRO: 0000020 07 28 db c3 d1 d6 1d 05 29 81 7f 3a 78          | .(......)..:x
RLB_PRO: [MAC] 0x0B
RLB_PRO: 0000000 01                                              | .
RLB_PRO: RekeyConf: server version = 1.1
RLB_PRO: [MAC] 0x0D
RLB_PRO: 0000000 ba d8 31 53 df                                  | ..1S.
RLB_PRO: DeviceTimeAns: [user]
RLB_PRO: [MAC] 0x02
RLB_PRO: 0000000 18 01                                           | ..
RLB_PRO: LinkCheckAns: [user]
RLB_PRO: [MAC] 0x03
RLB_PRO: 0000000 4f ff 00 01                                     | O...
RLB_PRO: LinkADRReq: dataRate = 4, txPower = 15, chMask = 0x00ff, chMaskCntl = 0, nbTrans = 1
RLB_PRO: PHY: SF = 8, BW = 125.000 kHz, CR = 4/5
RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
RLB_PRO: LinkADRAns: status = 0x07
Downlink data:
97BA6499232C4F443C27C7DC6AF61000
[LoRaWAN] RSSI:         -38.00 dBm
[LoRaWAN] SNR:          7.50 dB
[LoRaWAN] Frequency error:      1878.41 Hz
[LoRaWAN] Event information:
[LoRaWAN] Confirmed:    0
[LoRaWAN] Confirming:   1
[LoRaWAN] Datarate:     4
[LoRaWAN] Frequency:    867.500 MHz
[LoRaWAN] Output power: 16 dBm
[LoRaWAN] Frame count:  0
[LoRaWAN] Port:         0
[LoRaWAN] LinkCheck margin:     24
[LoRaWAN] LinkCheck count:      1
[LoRaWAN] DeviceTime Unix:      1711740456
[LoRaWAN] DeviceTime second:    1/223
[LoRaWAN] Next uplink in 1194s

StevenCellist · 2024-03-29T20:48:04Z

StevenCellist
Mar 29, 2024
Collaborator

All looks fine to me; the device correctly receives an LinkADRReq and processes this accordingly:

RLB_PRO: LinkADRReq: dataRate = 4, txPower = 15, chMask = 0x00ff, chMaskCntl = 0, nbTrans = 1
RLB_PRO: PHY: SF = 8, BW = 125.000 kHz, CR = 4/5

0 replies

HeadBoffin · 2024-03-29T21:49:43Z

HeadBoffin
Mar 29, 2024
Collaborator

@michapr, how long does the ADR algorithm take to process uplinks on TTN?

0 replies

michapr · 2024-03-29T22:30:21Z

michapr
Mar 29, 2024
Author

22:20:31.696 -> [LoRaWAN] Next uplink in 1193s
22:40:25.672 -> RLB_PRO: 
22:40:25.672 -> RLB_PRO: PHY: Frequency UL = 867.900 MHz
22:40:25.672 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
22:40:25.672 -> RLB_PRO: Uplink (FcntUp = 2) decoded:
22:40:25.672 -> RLB_PRO: 0000000 c0 00 78 56 5c 3e ce 3f 13 00 00 00 34 12 ba ab | ..xV\>.?....4...
22:40:25.672 -> RLB_PRO: 0000010 40 09 47 0b 26 80 02 00 0a 94 6e 71 a7 af 00 00 | @.G.&.....nq....
22:40:25.845 -> RLB_DBG: Timeout in 1648 ms
22:40:26.165 -> RLB_PRO: Uplink sent <-- Rx Delay start
22:40:26.165 -> RLB_PRO: 
22:40:26.165 -> RLB_PRO: PHY: Frequency DL = 867.900 MHz
22:40:26.165 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
22:40:31.199 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
22:40:31.408 -> RLB_PRO: Closing Rx1 window
22:40:31.504 -> RLB_PRO: Downlink (NFcntDown = 2) encoded:
22:40:31.504 -> RLB_PRO: 0000000 49 00 00 00 00 01 09 47 0b 26 02 00 00 00 00 0d | I......G.&......
22:40:31.534 -> RLB_PRO: 0000010 60 09 47 0b 26 85 02 00 ec a2 44 ab 22 12 44 dc | `.G.&.....D.".D.
22:40:31.534 -> RLB_PRO: 0000020 df                                              | .                 
22:40:31.534 -> RLB_PRO: [MAC] 0x03
22:40:31.534 -> RLB_PRO: 0000000 4f ff 00 01                                     | O...              
22:40:31.534 -> RLB_PRO: LinkADRReq: dataRate = 4, txPower = 15, chMask = 0x00ff, chMaskCntl = 0, nbTrans = 1
22:40:31.567 -> RLB_PRO: PHY: SF = 8, BW = 125.000 kHz, CR = 4/5

0 replies

michapr · 2024-03-30T07:24:27Z

michapr
Mar 30, 2024
Author

Additional info:
Starting today the device I have seen the error code -1116 (have seen it here yesterday sometimes, but could not reproduce):

08:05:20.976 -> ESP-ROM:esp32s3-20210327
08:05:20.976 -> Build:Mar 27 2021
08:05:20.976 -> rst:0x1 (POWERON),boot:0x29 (SPI_FAST_FLASH_BOOT)
08:05:20.976 -> SPIWP:0xee
08:05:20.976 -> mode:DIO, clock div:1
08:05:20.976 -> load:0x3fce3808,len:0x43c
08:05:20.976 -> load:0x403c9700,len:0xbec
08:05:20.996 -> load:0x403cc700,len:0x2a3c
08:05:20.996 -> SHA-256 comparison failed:
08:05:20.996 -> Calculated: dcde8d8a4817d9bf5d5d69a7247667264e4e10ac7493514868b61f5aa6146539
08:05:20.996 -> Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
08:05:20.996 -> Attempting to boot anyway...
08:05:20.996 -> entry 0x403c98d8
08:05:26.047 -> 
08:05:26.047 -> Setup
08:05:26.047 -> Initalise the radio
08:05:26.097 -> RLB_DBG: RadioLib Debug Info
08:05:26.097 -> RLB_DBG: Version:  6.5.0.0
08:05:26.097 -> RLB_DBG: Platform: ESP32
08:05:26.097 -> RLB_DBG: Compiled: Mar 29 2024 18:40:51
08:05:26.097 -> 
08:05:26.097 -> RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
08:05:26.097 -> RLB_DBG: 0000320 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 | SX1261 V2D 2D02.
08:05:26.112 -> RLB_DBG: 
08:05:26.112 -> RLB_DBG: M	SX126x
08:05:26.144 -> Join ('login') to the LoRaWAN Network
08:05:26.144 -> RLB_PRO: Configuration mismatch (checksum: 0, mode: 0, class: 0, plan: 1)
08:05:26.144 -> RLB_PRO: Nonces buffer:
08:05:26.144 -> RLB_PRO: 0000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ................
08:05:26.144 -> RLB_PRO: Clearing buffer and starting fresh
08:05:26.144 -> RLB_PRO: Setting up dynamic channels
08:05:26.176 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
08:05:26.176 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
08:05:26.176 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
08:05:26.176 -> RLB_PRO: [MAC] 0x03
08:05:26.176 -> RLB_PRO: 0000000 20 00 00 80                                     |  ...              
08:05:26.176 -> RLB_PRO: LinkADRReq: dataRate = 2, txPower = 0, chMask = 0x0000, chMaskCntl = 0, nbTrans = 0
08:05:26.208 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:05:26.208 -> RLB_PRO: PHY: TX = 16 dBm
08:05:26.208 -> RLB_PRO: LinkADRAns: status = 0x07
08:05:26.208 -> RLB_PRO: [MAC] 0x04
08:05:26.208 -> RLB_PRO: 0000000 07                                              | .                 
08:05:26.208 -> RLB_PRO: DutyCycleReq: max duty cycle = 1/2^7
08:05:26.208 -> RLB_PRO: [MAC] 0x05
08:05:26.208 -> RLB_PRO: 0000000 00 d2 ad 84                                     | ....              
08:05:26.240 -> RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 0, freq = 869.525024
08:05:26.240 -> RLB_PRO: RXParamSetupAns: status = 0x07
08:05:26.240 -> RLB_PRO: [MAC] 0x08
08:05:26.240 -> RLB_PRO: 0000000 01                                              | .                 
08:05:26.240 -> RLB_PRO: RXTimingSetupReq: delay = 1 sec
08:05:26.240 -> RLB_PRO: [MAC] 0x09
08:05:26.240 -> RLB_PRO: 0000000 05                                              | .                 
08:05:26.272 -> RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 0, maxEirp = 16 dBm
08:05:26.272 -> RLB_PRO: [MAC] 0x0C
08:05:26.272 -> RLB_PRO: 0000000 65                                              | e                 
08:05:26.272 -> RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
08:05:26.272 -> RLB_PRO: [MAC] 0x0F
08:05:26.272 -> RLB_PRO: 0000000 fa                                              | .                 
08:05:26.310 -> RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
08:05:26.310 -> RLB_PRO: RejoinParamSetupAns: status = 0x03
08:05:26.395 -> RLB_PRO: 
08:05:26.395 -> RLB_PRO: PHY: Frequency UL = 868.300 MHz
08:05:26.395 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:05:26.395 -> RLB_DBG: Timeout in 1853 ms
08:05:26.740 -> RLB_PRO: Join-request sent <-- Rx Delay start
08:05:26.785 -> RLB_PRO: 
08:05:26.785 -> RLB_PRO: PHY: Frequency DL = 868.300 MHz
08:05:26.785 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:05:31.779 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
08:05:32.311 -> RLB_PRO: Closing Rx1 window
08:05:32.311 -> RLB_PRO: PHY: Frequency DL = 869.525 MHz
08:05:32.311 -> RLB_PRO: PHY: SF = 12, BW = 125.000 kHz, CR = 4/5
08:05:32.774 -> RLB_PRO: Opening Rx2 window (683552 us timeout)... <-- Rx Delay end 
08:05:33.439 -> RLB_PRO: Closing Rx2 window
08:05:33.439 -> Join failed(-1116)

After press reset all was "ok" again, but with SF10BW125:

08:08:58.183 -> ESP-ROM:esp32s3-20210327
08:08:58.183 -> Build:Mar 27 2021
08:08:58.183 -> rst:0x1 (POWERON),boot:0x28 (SPI_FAST_FLASH_BOOT)
08:08:58.183 -> SPIWP:0xee
08:08:58.183 -> mode:DIO, clock div:1
08:08:58.183 -> load:0x3fce3808,len:0x43c
08:08:58.183 -> load:0x403c9700,len:0xbec
08:08:58.183 -> load:0x403cc700,len:0x2a3c
08:08:58.183 -> SHA-256 comparison failed:
08:08:58.183 -> Calculated: dcde8d8a4817d9bf5d5d69a7247667264e4e10ac7493514868b61f5aa6146539
08:08:58.183 -> Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
08:08:58.229 -> Attempting to boot anyway...
08:08:58.229 -> entry 0x403c98d8
08:09:03.309 -> 
08:09:03.309 -> Setup
08:09:03.309 -> Initalise the radio
08:09:03.309 -> RLB_DBG: RadioLib Debug Info
08:09:03.309 -> RLB_DBG: Version:  6.5.0.0
08:09:03.309 -> RLB_DBG: Platform: ESP32
08:09:03.309 -> RLB_DBG: Compiled: Mar 29 2024 18:40:51
08:09:03.309 -> 
08:09:03.309 -> RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
08:09:03.309 -> RLB_DBG: 0000320 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 | SX1261 V2D 2D02.
08:09:03.357 -> RLB_DBG: 
08:09:03.357 -> RLB_DBG: M	SX126x
08:09:03.382 -> Join ('login') to the LoRaWAN Network
08:09:03.382 -> RLB_PRO: Configuration mismatch (checksum: 0, mode: 0, class: 0, plan: 1)
08:09:03.382 -> RLB_PRO: Nonces buffer:
08:09:03.382 -> RLB_PRO: 0000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ................
08:09:03.382 -> RLB_PRO: Clearing buffer and starting fresh
08:09:03.382 -> RLB_PRO: Setting up dynamic channels
08:09:03.382 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
08:09:03.414 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
08:09:03.414 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
08:09:03.414 -> RLB_PRO: [MAC] 0x03
08:09:03.414 -> RLB_PRO: 0000000 20 00 00 80                                     |  ...              
08:09:03.414 -> RLB_PRO: LinkADRReq: dataRate = 2, txPower = 0, chMask = 0x0000, chMaskCntl = 0, nbTrans = 0
08:09:03.414 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:09:03.446 -> RLB_PRO: PHY: TX = 16 dBm
08:09:03.446 -> RLB_PRO: LinkADRAns: status = 0x07
08:09:03.446 -> RLB_PRO: [MAC] 0x04
08:09:03.446 -> RLB_PRO: 0000000 07                                              | .                 
08:09:03.446 -> RLB_PRO: DutyCycleReq: max duty cycle = 1/2^7
08:09:03.446 -> RLB_PRO: [MAC] 0x05
08:09:03.446 -> RLB_PRO: 0000000 00 d2 ad 84                                     | ....              
08:09:03.446 -> RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 0, freq = 869.525024
08:09:03.480 -> RLB_PRO: RXParamSetupAns: status = 0x07
08:09:03.480 -> RLB_PRO: [MAC] 0x08
08:09:03.480 -> RLB_PRO: 0000000 01                                              | .                 
08:09:03.480 -> RLB_PRO: RXTimingSetupReq: delay = 1 sec
08:09:03.480 -> RLB_PRO: [MAC] 0x09
08:09:03.480 -> RLB_PRO: 0000000 05                                              | .                 
08:09:03.480 -> RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 0, maxEirp = 16 dBm
08:09:03.511 -> RLB_PRO: [MAC] 0x0C
08:09:03.511 -> RLB_PRO: 0000000 65                                              | e                 
08:09:03.511 -> RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
08:09:03.511 -> RLB_PRO: [MAC] 0x0F
08:09:03.511 -> RLB_PRO: 0000000 fa                                              | .                 
08:09:03.511 -> RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
08:09:03.548 -> RLB_PRO: RejoinParamSetupAns: status = 0x03
08:09:03.627 -> RLB_PRO: 
08:09:03.627 -> RLB_PRO: PHY: Frequency UL = 868.500 MHz
08:09:03.627 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:09:03.627 -> RLB_DBG: Timeout in 1853 ms
08:09:04.007 -> RLB_PRO: Join-request sent <-- Rx Delay start
08:09:04.007 -> RLB_PRO: 
08:09:04.007 -> RLB_PRO: PHY: Frequency DL = 868.500 MHz
08:09:04.007 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:09:09.001 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
08:09:09.235 -> RLB_PRO: Closing Rx1 window
08:09:09.440 -> RLB_PRO: joinAcceptMsg:
08:09:09.440 -> RLB_PRO: 0000000 20 21 00 00 13 00 00 1a 6c 0b 26 83 05 18 4f 84 |  !......l.&...O.
08:09:09.440 -> RLB_PRO: 0000010 e8 56 84 b8 5e 84 88 66 84 58 6e 84 00 92 4a fa | .V..^..f.Xn...J.
08:09:09.472 -> RLB_PRO: 0000020 e6                                              | .                 
08:09:09.472 -> RLB_PRO: JoinNoncePrev: 0, JoinNonce: 33
08:09:09.472 -> RLB_PRO: LoRaWAN revision: 1.1
08:09:09.472 -> RLB_PRO: [MAC] 0x05
08:09:09.472 -> RLB_PRO: 0000000 03 d2 ad 84                                     | ....              
08:09:09.472 -> RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 3, freq = 869.525024
08:09:09.506 -> RLB_PRO: RXParamSetupAns: status = 0x07
08:09:09.506 -> RLB_PRO: [MAC] 0x08
08:09:09.506 -> RLB_PRO: 0000000 05                                              | .                 
08:09:09.506 -> RLB_PRO: RXTimingSetupReq: delay = 5 sec
08:09:09.542 -> RLB_PRO: Setting up dynamic channels
08:09:09.542 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
08:09:09.542 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
08:09:09.542 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
08:09:09.542 -> RLB_PRO: Processing CFList
08:09:09.542 -> RLB_PRO: [MAC] 0x07
08:09:09.542 -> RLB_PRO: 0000000 03 18 4f 84 50                                  | ..O.P             
08:09:09.574 -> RLB_PRO: NewChannelReq:
08:09:09.574 -> RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
08:09:09.574 -> RLB_PRO: NewChannelAns: status = 0x03
08:09:09.574 -> RLB_PRO: [MAC] 0x07
08:09:09.574 -> RLB_PRO: 0000000 04 e8 56 84 50                                  | ..V.P             
08:09:09.574 -> RLB_PRO: NewChannelReq:
08:09:09.574 -> RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
08:09:09.606 -> RLB_PRO: NewChannelAns: status = 0x03
08:09:09.606 -> RLB_PRO: [MAC] 0x07
08:09:09.606 -> RLB_PRO: 0000000 05 b8 5e 84 50                                  | ..^.P             
08:09:09.606 -> RLB_PRO: NewChannelReq:
08:09:09.606 -> RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
08:09:09.606 -> RLB_PRO: NewChannelAns: status = 0x03
08:09:09.606 -> RLB_PRO: [MAC] 0x07
08:09:09.606 -> RLB_PRO: 0000000 06 88 66 84 50                                  | ..f.P             
08:09:09.639 -> RLB_PRO: NewChannelReq:
08:09:09.639 -> RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
08:09:09.639 -> RLB_PRO: NewChannelAns: status = 0x03
08:09:09.639 -> RLB_PRO: [MAC] 0x07
08:09:09.639 -> RLB_PRO: 0000000 07 58 6e 84 50                                  | .Xn.P             
08:09:09.678 -> RLB_PRO: NewChannelReq:
08:09:09.678 -> RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
08:09:09.678 -> RLB_PRO: NewChannelAns: status = 0x03
08:09:09.678 -> [LoRaWAN] DevAddr: 260B6C1A
08:09:09.678 -> Ready!
08:09:09.678 -> 
08:09:09.678 -> [LoRaWAN] Requesting LinkCheck and DeviceTime
08:09:09.751 -> RLB_PRO: 
08:09:09.751 -> RLB_PRO: PHY: Frequency UL = 867.500 MHz
08:09:09.751 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:09:09.751 -> RLB_PRO: Uplink MAC payload (3 commands):
08:09:09.751 -> RLB_PRO: 0000000 0b 01 02 0d                                     | ....              
08:09:09.751 -> RLB_PRO: Uplink (FcntUp = 0) decoded:
08:09:09.751 -> RLB_PRO: 0000000 c0 00 78 56 5c 3e ce 3f 13 00 00 00 34 12 ba ab | ..xV\>.?....4...
08:09:09.787 -> RLB_PRO: 0000010 80 1a 6c 0b 26 84 00 00 19 34 d9 1a 0a 0f ce 6a | ..l.&....4.....j
08:09:09.787 -> RLB_PRO: 0000020 14 00 ce 3f                                     | ...?              
08:09:09.977 -> RLB_DBG: Timeout in 1853 ms
08:09:10.358 -> RLB_PRO: Uplink sent <-- Rx Delay start
08:09:10.358 -> RLB_PRO: 
08:09:10.358 -> RLB_PRO: PHY: Frequency DL = 867.500 MHz
08:09:10.358 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
08:09:15.346 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
08:09:15.560 -> RLB_PRO: Closing Rx1 window
08:09:15.734 -> RLB_PRO: Downlink (NFcntDown = 0) encoded:
08:09:15.767 -> RLB_PRO: 0000000 49 00 00 00 00 01 1a 6c 0b 26 00 00 00 00 00 19 | I......l.&......
08:09:15.767 -> RLB_PRO: 0000010 60 1a 6c 0b 26 a0 00 00 00 bf 8e ea 37 fa d8 ed | `.l.&.......7...
08:09:15.767 -> RLB_PRO: 0000020 17 ba f6 65 24 0a b5 5c 0e 18 79 3e ac          | ...e$..\..y>.     
08:09:15.767 -> RLB_PRO: [MAC] 0x0B
08:09:15.767 -> RLB_PRO: 0000000 01                                              | .                 
08:09:15.798 -> RLB_PRO: RekeyConf: server version = 1.1
08:09:15.798 -> RLB_PRO: [MAC] 0x0D
08:09:15.798 -> RLB_PRO: 0000000 28 7d 32 53 03                                  | (}2S.             
08:09:15.798 -> RLB_PRO: DeviceTimeAns: [user]
08:09:15.798 -> RLB_PRO: [MAC] 0x02
08:09:15.798 -> RLB_PRO: 0000000 17 01                                           | ..                
08:09:15.798 -> RLB_PRO: LinkCheckAns: [user]
08:09:15.798 -> RLB_PRO: [MAC] 0x03
08:09:15.798 -> RLB_PRO: 0000000 4f ff 00 01                                     | O...              
08:09:15.830 -> RLB_PRO: LinkADRReq: dataRate = 4, txPower = 15, chMask = 0x00ff, chMaskCntl = 0, nbTrans = 1
08:09:15.830 -> RLB_PRO: PHY: SF = 8, BW = 125.000 kHz, CR = 4/5
08:09:15.830 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
08:09:15.830 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
08:09:15.830 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
08:09:15.862 -> RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
08:09:15.862 -> RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
08:09:15.862 -> RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
08:09:15.862 -> RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
08:09:15.862 -> RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
08:09:15.862 -> RLB_PRO: LinkADRAns: status = 0x07
08:09:15.862 -> Downlink data: 
08:09:15.894 -> 561D26E211B86201955B066147FD1000
08:09:15.894 -> [LoRaWAN] RSSI:		-45.00 dBm
08:09:15.894 -> [LoRaWAN] SNR:		8.50 dB
08:09:15.894 -> [LoRaWAN] Frequency error:	1897.78 Hz
08:09:15.894 -> [LoRaWAN] Event information:
08:09:15.894 -> [LoRaWAN] Confirmed:	0
08:09:15.894 -> [LoRaWAN] Confirming:	1
08:09:15.894 -> [LoRaWAN] Datarate:	4
08:09:15.894 -> [LoRaWAN] Frequency:	867.500 MHz
08:09:15.894 -> [LoRaWAN] Output power:	16 dBm
08:09:15.894 -> [LoRaWAN] Frame count:	0
08:09:15.894 -> [LoRaWAN] Port:		0
08:09:15.894 -> [LoRaWAN] LinkCheck margin:	23
08:09:15.942 -> [LoRaWAN] LinkCheck count:	1
08:09:15.942 -> [LoRaWAN] DeviceTime Unix:	1711782550
08:09:15.942 -> [LoRaWAN] DeviceTime second:	1/3
08:09:15.942 -> [LoRaWAN] Next uplink in 1194s

Yesterday late evening have seen in TTN console that sometimes the DR was ok - in interface was logged SF7BW125 (but I have not an Arduino-log). Will check today, if I have got such a log will provide it....

With latest release the same device was really working stable some weeks (in deep sleep mode) all the time with SF7BW125 even after reboot and without errors (but with saved sessions). That's why I think that maybe any difference between the versions?

Thank you for your time!

1 reply

StevenCellist Mar 30, 2024
Collaborator

Well, as you know from your other topic, your device currently does not restore sessions. This is also (a bit implicitly) visible in these logs:

08:09:03.382 -> RLB_PRO: Configuration mismatch (checksum: 0, mode: 0, class: 0, plan: 1)

and

08:09:03.382 -> RLB_PRO: Clearing buffer and starting fresh

And subsequently, a new join-request is sent:

08:09:04.007 -> RLB_PRO: Join-request sent <-- Rx Delay start

Combining these, it is unsurprising that ADR doesn't work, because every time you reset your device / every time a new join-request is sent, all previous information is lost or discarded. So it starts back up at SF10.
If you leave the device running without reboots, it does not lose its session, and is indeed able to 'listen' to the ADR commands, and processes them nicely, dropping you down to SF7.

TL;DR: fix your sessions and it will work as expected.

michapr · 2024-03-30T08:54:30Z

michapr
Mar 30, 2024
Author

You are right, this was a "wrong" debug log - after reboot.

But I do not use the sleep/reset mode in this time, I'm using your original example code with delay() ... and here I see this issue.
After delay time can see this log:

09:29:46.961 -> 
09:29:46.961 -> Stack smashing protect failure!
09:29:46.961 -> 
09:29:46.961 -> 
09:29:46.961 -> abort() was called at PC 0x4201422b on core 1
09:29:46.961 -> 
09:29:46.961 -> 
09:29:46.961 -> Backtrace:0x403777be:0x3fce2ed00x4037a5ad:0x3fce2ef0 0x4037fba5:0x3fce2f10 0x4201422b:0x3fce2f90 0x42001fa9:0x3fce2fb0 0x4200abf1:0x3fce3030 
09:29:46.961 -> 
09:29:46.961 -> 
09:29:46.961 -> 
09:29:46.961 -> 
09:29:46.961 -> ELF file SHA256: 0000000000000000
09:29:46.961 -> 
09:29:46.961 -> Rebooting...
09:29:46.961 -> �ESP-ROM:esp32s3-20210327
09:29:47.012 -> Build:Mar 27 2021
09:29:47.012 -> rst:0xc (RTC_SW_CPU_RST),boot:0x28 (SPI_FAST_FLASH_BOOT)
09:29:47.012 -> Saved PC:0x4202b7b2
09:29:47.012 -> SPIWP:0xee
09:29:47.012 -> mode:DIO, clock div:1
09:29:47.012 -> load:0x3fce3808,len:0x43c
09:29:47.012 -> load:0x403c9700,len:0xbec
09:29:47.012 -> load:0x403cc700,len:0x2a3c
09:29:47.012 -> SHA-256 comparison failed:
09:29:47.012 -> Calculated: dcde8d8a4817d9bf5d5d69a7247667264e4e10ac7493514868b61f5aa6146539
09:29:47.012 -> Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
09:29:47.039 -> Attempting to boot anyway...
09:29:52.113 -> 
09:29:52.113 -> Setup
09:29:52.113 -> Initalise the radio
09:29:52.113 -> RLB_DBG: RadioLib Debug Info
09:29:52.113 -> RLB_DBG: Version:  6.5.0.0
09:29:52.113 -> RLB_DBG: Platform: ESP32
09:29:52.113 -> RLB_DBG: Compiled: Mar 29 2024 18:40:51
09:29:52.113 -> 
09:29:52.113 -> RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
09:29:52.161 -> RLB_DBG: 0000320 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 | SX1261 V2D 2D02.
09:29:52.161 -> RLB_DBG: 
09:29:52.161 -> RLB_DBG: M	SX126x
09:29:52.192 -> Join ('login') to the LoRaWAN Network
09:29:52.192 -> RLB_PRO: Configuration mismatch (checksum: 0, mode: 0, class: 0, plan: 1)
09:29:52.192 -> RLB_PRO: Nonces buffer:
09:29:52.192 -> RLB_PRO: 0000000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 | ................
09:29:52.192 -> RLB_PRO: Clearing buffer and starting fresh
09:29:52.192 -> RLB_PRO: Setting up dynamic channels
09:29:52.192 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
09:29:52.224 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
09:29:52.224 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
09:29:52.224 -> RLB_PRO: [MAC] 0x03
09:29:52.224 -> RLB_PRO: 0000000 20 00 00 80                                     |  ...              
09:29:52.224 -> RLB_PRO: LinkADRReq: dataRate = 2, txPower = 0, chMask = 0x0000, chMaskCntl = 0, nbTrans = 0
09:29:52.224 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
09:29:52.256 -> RLB_PRO: PHY: TX = 16 dBm
09:29:52.256 -> RLB_PRO: LinkADRAns: status = 0x07
09:29:52.256 -> RLB_PRO: [MAC] 0x04
09:29:52.256 -> RLB_PRO: 0000000 07                                              | .                 
09:29:52.256 -> RLB_PRO: DutyCycleReq: max duty cycle = 1/2^7
09:29:52.256 -> RLB_PRO: [MAC] 0x05
09:29:52.256 -> RLB_PRO: 0000000 00 d2 ad 84                                     | ....              
09:29:52.256 -> RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 0, freq = 869.525024
09:29:52.288 -> RLB_PRO: RXParamSetupAns: status = 0x07
09:29:52.288 -> RLB_PRO: [MAC] 0x08
09:29:52.288 -> RLB_PRO: 0000000 01                                              | .                 
09:29:52.288 -> RLB_PRO: RXTimingSetupReq: delay = 1 sec
09:29:52.288 -> RLB_PRO: [MAC] 0x09
09:29:52.288 -> RLB_PRO: 0000000 05                                              | .                 
09:29:52.288 -> RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 0, maxEirp = 16 dBm
09:29:52.320 -> RLB_PRO: [MAC] 0x0C
09:29:52.320 -> RLB_PRO: 0000000 65                                              | e                 
09:29:52.320 -> RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
09:29:52.320 -> RLB_PRO: [MAC] 0x0F
09:29:52.320 -> RLB_PRO: 0000000 fa                                              | .                 
09:29:52.320 -> RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
09:29:52.353 -> RLB_PRO: RejoinParamSetupAns: status = 0x03
09:29:52.434 -> RLB_PRO: 
09:29:52.434 -> RLB_PRO: PHY: Frequency UL = 868.300 MHz
09:29:52.434 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
09:29:52.434 -> RLB_DBG: Timeout in 1853 ms
09:29:52.811 -> RLB_PRO: Join-request sent <-- Rx Delay start
09:29:52.811 -> RLB_PRO: 
09:29:52.811 -> RLB_PRO: PHY: Frequency DL = 868.300 MHz
09:29:52.811 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
09:29:57.792 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
09:29:58.025 -> RLB_PRO: Closing Rx1 window
09:29:58.267 -> RLB_PRO: joinAcceptMsg:
09:29:58.267 -> RLB_PRO: 0000000 20 25 00 00 13 00 00 74 5e 0b 26 83 05 18 4f 84 |  ^.&...O.
09:29:58.267 -> RLB_PRO: 0000010 e8 56 84 b8 5e 84 88 66 84 58 6e 84 00 b0 42 0d | .V..^..f.Xn...B.
09:29:58.267 -> RLB_PRO: 0000020 a6                                              | .                 
09:29:58.267 -> RLB_PRO: JoinNoncePrev: 0, JoinNonce: 37
09:29:58.299 -> RLB_PRO: LoRaWAN revision: 1.1
09:29:58.299 -> RLB_PRO: [MAC] 0x05
09:29:58.299 -> RLB_PRO: 0000000 03 d2 ad 84                                     | ....              
09:29:58.299 -> RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 3, freq = 869.525024
09:29:58.299 -> RLB_PRO: RXParamSetupAns: status = 0x07
09:29:58.331 -> RLB_PRO: [MAC] 0x08
09:29:58.331 -> RLB_PRO: 0000000 05                 
09:29:58.331 -> RLB_PRO: RXTimingSetupReq: delay = 5 sec
09:29:58.331 -> RLB_PRO: Setting up dynamic channels
09:29:58.331 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
09:29:58.331 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
09:29:58.331 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
09:29:58.363 -> RLB_PRO: Processing CFList
09:29:58.363 -> RLB_PRO: [MAC] 0x07
09:29:58.363 -> RLB_PRO: 0000000 03 18 4f 84 50                                  | ..O.P             
09:29:58.363 -> RLB_PRO: NewChannelReq:
09:29:58.363 -> RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
09:29:58.363 -> RLB_PRO: NewChannelAns: status = 0x03
09:29:58.395 -> RLB_PRO: [MAC] 0x07
09:29:58.395 -> RLB_PRO: 0000000 04 e8 56 84 50                                  | ..V.P             
09:29:58.395 -> RLB_PRO: NewChannelReq:
09:29:58.395 -> RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
09:29:58.395 -> RLB_PRO: NewChannelAns: status = 0x03
09:29:58.395 -> RLB_PRO: [MAC] 0x07
09:29:58.395 -> RLB_PRO: 0000000 05 b8 5e 84 50                                  | ..^.P             
09:29:58.427 -> RLB_PRO: NewChannelReq:
09:29:58.427 -> RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
09:29:58.427 -> RLB_PRO: NewChannelAns: status = 0x03
09:29:58.427 -> RLB_PRO: [MAC] 0x07
09:29:58.427 -> RLB_PRO: 0000000 06 88 66 84 50                                  | ..f.P             
09:29:58.427 -> RLB_PRO: NewChannelReq:
09:29:58.459 -> RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
09:29:58.459 -> RLB_PRO: NewChannelAns: status = 0x03
09:29:58.459 -> RLB_PRO: [MAC] 0x07
09:29:58.459 -> RLB_PRO: 0000000 07 58 6e 84 50                                  | .Xn.P             
09:29:58.459 -> RLB_PRO: NewChannelReq:
09:29:58.459 -> RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
09:29:58.459 -> RLB_PRO: NewChannelAns: status = 0x03
09:29:58.500 -> [LoRaWAN] DevAddr: 260B5E74
09:29:58.500 -> Ready!
09:29:58.500 -> 
09:29:58.500 -> [LoRaWAN] Requesting LinkCheck and DeviceTime
09:29:58.532 -> RLB_PRO: 
09:29:58.532 -> RLB_PRO: PHY: Frequency UL = 867.100 MHz
09:29:58.564 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
09:29:58.564 -> RLB_PRO: Uplink MAC payload (3 commands):
09:29:58.564 -> RLB_PRO: 0000000 0b 01 02 0d                                     | ....              
09:29:58.564 -> RLB_PRO: Uplink (FcntUp = 0) decoded:
09:29:58.564 -> RLB_PRO: 0000000 c0 00 78 56 5c 3e ce 3f 13 00 00 00 34 12 ba ab | ..xV\>.?....4...
09:29:58.606 -> RLB_PRO: 0000010 80 74 5e 0b 26 84 00 00 f6 28 60 f7 0a a1 70 b2 | .t^.&....(`...p.
09:29:58.606 -> RLB_PRO: 0000020 14 00 ce 3f                                     | ...?              
09:29:58.870 -> RLB_DBG: Timeout in 1853 ms
09:29:59.249 -> RLB_PRO: Uplink sent <-- Rx Delay start
09:29:59.249 -> RLB_PRO: 
09:29:59.249 -> RLB_PRO: PHY: Frequency DL = 867.100 MHz
09:29:59.249 -> RLB_PRO: PHY: SF = 10, BW = 125.000 kHz, CR = 4/5
09:30:04.244 -> RLB_PRO: Opening Rx1 window (226848 us timeout)... <-- Rx Delay end 
09:30:04.476 -> RLB_PRO: Closing Rx1 window
09:30:04.630 -> RLB_PRO: Downlink (NFcntDown = 0) encoded:
09:30:04.662 -> RLB_PRO: 0000000 49 00 00 00 00 01 74 5e 0b 26 00 00 00 00 00 19 | I.....t^.&......
09:30:04.662 -> RLB_PRO: 0000010 60 74 5e 0b 26 a0 00 00 00 42 01 4f be 7d 1b d4 | `t^.&....B.O.}..
09:30:04.662 -> RLB_PRO: 0000020 6b c1 7e 96 6a d4 bd 5d 47 29 79 b2 48          | k.~.j..]G)y.H     
09:30:04.662 -> RLB_PRO: [MAC] 0x0B
09:30:04.662 -> RLB_PRO: 0000000 01                                              | .                 
09:30:04.694 -> RLB_PRO: RekeyConf: server version = 1.1
09:30:04.694 -> RLB_PRO: [MAC] 0x0D
09:30:04.694 -> RLB_PRO: 0000000 19 90 32 53 33                                  | ..2S3             
09:30:04.694 -> RLB_PRO: DeviceTimeAns: [user]
09:30:04.694 -> RLB_PRO: [MAC] 0x02
09:30:04.694 -> RLB_PRO: 0000000 19 01          
09:30:04.694 -> RLB_PRO: LinkCheckAns: [user]
09:30:04.694 -> RLB_PRO: [MAC] 0x03
09:30:04.694 -> RLB_PRO: 0000000 5f ff 00 01                                     | _...              
09:30:04.726 -> RLB_PRO: LinkADRReq: dataRate = 5, txPower = 15, chMask = 0x00ff, chMaskCntl = 0, nbTrans = 1
09:30:04.726 -> RLB_PRO: PHY: SF = 7, BW = 125.000 kHz, CR = 4/5
09:30:04.726 -> RLB_PRO: UL:   0 1 868.100 (0 - 5) | DL:   0 1 868.100 (0 - 5)
09:30:04.726 -> RLB_PRO: UL:   1 1 868.300 (0 - 5) | DL:   1 1 868.300 (0 - 5)
09:30:04.726 -> RLB_PRO: UL:   2 1 868.500 (0 - 5) | DL:   2 1 868.500 (0 - 5)
09:30:04.758 -> RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
09:30:04.758 -> RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
09:30:04.758 -> RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
09:30:04.758 -> RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
09:30:04.758 -> RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
09:30:04.758 -> RLB_PRO: LinkADRAns: status = 0x07
09:30:04.758 -> Downlink data: 
09:30:04.790 -> 0E28602808FD0DA6FF7DC83C03541000
09:30:04.790 -> [LoRaWAN] RSSI:		-49.00 dBm
09:30:04.790 -> [LoRaWAN] SNR:		8.25 dB
09:30:04.790 -> [LoRaWAN] Frequency error:	1913.28 Hz
09:30:04.790 -> [LoRaWAN] Event information:
09:30:04.790 -> [LoRaWAN] Confirmed:	0
09:30:04.790 -> [LoRaWAN] Confirming:	1
09:30:04.790 -> [LoRaWAN] Datarate:	5
09:30:04.790 -> [LoRaWAN] Frequency:	867.100 MHz
09:30:04.790 -> [LoRaWAN] Output power:	16 dBm
09:30:04.790 -> [LoRaWAN] Frame count:	0
09:30:04.790 -> [LoRaWAN] Port:		0
09:30:04.790 -> [LoRaWAN] LinkCheck margin:	25
09:30:04.830 -> [LoRaWAN] LinkCheck count:	1
09:30:04.830 -> [LoRaWAN] DeviceTime Unix:	1711787399
09:30:04.830 -> [LoRaWAN] DeviceTime second:	1/51
09:30:04.830 -> [LoRaWAN] Next uplink in 1194s

Sorry for confusion....
(first lines look strange for me... device is really rebooting, why... - and why I have not seen it before....)

1 reply

HeadBoffin Mar 30, 2024
Collaborator

After delay time can see this log:

The device has indeed rebooted, so despite waiting for the next uplink, it's re-started so it ends up with a clean slate with ADR reset.

The "smoke test" is LoRaWAN_Starter.ino - the reference one is a bit busy with lots of extras and going back to basics to check the device can do the delay without a reboot and that ADR is working as expected before adding anything in. For the starter you only need to change the items in config.h - your EUI's, keys and region.

BTW, the stack defaults to ADR being on.

michapr · 2024-03-30T11:31:35Z

michapr
Mar 30, 2024
Author

Yes, I never have thought about that device could reboot after delay - that's why haven't seen it (a very very rare case for me....).
With previous firmware device was sleeping - so other case....

But I have seen now that device is not rebooting every time.
Now - after a normal delay() I see not more reboots - and the ADR is working as expected - get SF7BW125.

No changes at all... only waiting some time.

Here a part of the log after switching to normal work.
If you need complete log (if it is interesting for you) tell me.

11:39:15.908 -> RLB_PRO: UL:   3 1 867.100 (0 - 5) | DL:   3 1 867.100 (0 - 5)
11:39:15.908 -> RLB_PRO: UL:   4 1 867.300 (0 - 5) | DL:   4 1 867.300 (0 - 5)
11:39:15.908 -> RLB_PRO: UL:   5 1 867.500 (0 - 5) | DL:   5 1 867.500 (0 - 5)
11:39:15.908 -> RLB_PRO: UL:   6 1 867.700 (0 - 5) | DL:   6 1 867.700 (0 - 5)
11:39:15.908 -> RLB_PRO: UL:   7 1 867.900 (0 - 5) | DL:   7 1 867.900 (0 - 5)
11:39:15.940 -> RLB_PRO: LinkADRAns: status = 0x07
11:39:15.940 -> <MAC commands only>
11:39:15.940 -> [LoRaWAN] RSSI:		-45.00 dBm
11:39:15.940 -> [LoRaWAN] SNR:		8.50 dB
11:39:15.940 -> [LoRaWAN] Frequency error:	1946.22 Hz
11:39:15.940 -> [LoRaWAN] Event information:
11:39:15.940 -> [LoRaWAN] Confirmed:	7
11:39:15.940 -> [LoRaWAN] Confirming:	0
11:39:15.940 -> [LoRaWAN] Datarate:	0
11:39:15.940 -> [LoRaWAN] Frequency:	0.000 MHz
11:39:15.940 -> [LoRaWAN] Output power:	12336 dBm
11:39:15.940 -> [LoRaWAN] Frame count:	0
11:39:15.981 -> [LoRaWAN] Port:		0
11:39:15.981 -> [LoRaWAN] Next uplink in 300s
11:44:16.038 -> RLB_PRO: 
11:44:16.038 -> RLB_PRO: PHY: Frequency UL = 868.300 MHz
11:44:16.038 -> RLB_PRO: PHY: SF = 7, BW = 125.000 kHz, CR = 4/5
11:44:16.038 -> RLB_PRO: Uplink MAC payload (1 commands):
11:44:16.038 -> RLB_PRO: 0000000 03 07                                           | ..                
11:44:16.038 -> RLB_PRO: Uplink (FcntUp = 3) decoded:
11:44:16.038 -> RLB_PRO: 0000000 c0 00 78 56 5c 3e ce 3f 13 00 00 00 34 12 ba ab | ..xV\>.?....4...
11:44:16.085 -> RLB_PRO: 0000010 40 74 59 0b 26 82 03 00 e0 34 0a c9 ac f9 00 00 | @tY.&....4......
11:44:16.085 -> RLB_PRO: 0000020 14 00                                           | ..                
11:44:16.156 -> RLB_DBG: Timeout in 257 ms
11:44:16.233 -> RLB_PRO: Uplink sent <-- Rx Delay start
11:44:16.233 -> RLB_PRO: 
11:44:16.233 -> RLB_PRO: PHY: Frequency DL = 868.300 MHz
11:44:16.233 -> RLB_PRO: PHY: SF = 7, BW = 125.000 kHz, CR = 4/5
11:44:21.220 -> RLB_PRO: Opening Rx1 window (45856 us timeout)... <-- Rx Delay end 
11:44:21.271 -> RLB_PRO: Closing Rx1 window
11:44:21.271 -> RLB_PRO: PHY: Frequency DL = 869.525 MHz
11:44:21.297 -> RLB_PRO: PHY: SF = 9, BW = 125.000 kHz, CR = 4/5
11:44:22.206 -> RLB_PRO: Opening Rx2 window (123424 us timeout)... <-- Rx Delay end 
11:44:22.347 -> RLB_PRO: Closing Rx2 window
11:44:22.347 -> [LoRaWAN] Next uplink in 300s
11:49:22.419 -> RLB_PRO: 
11:49:22.419 -> RLB_PRO: PHY: Frequency UL = 867.100 MHz
11:49:22.419 -> RLB_PRO: PHY: SF = 7, BW = 125.000 kHz, CR = 4/5
11:49:22.419 -> RLB_PRO: Uplink (FcntUp = 4) decoded:
....

0 replies

michapr · 2024-03-31T08:52:53Z

michapr
Mar 31, 2024
Author

I have seen that the ESP32 reboot only occurs when you call these two command requests: link_check and device_time

  if(fcntUp % 64 == 0) {
    Serial.println(F("[LoRaWAN] Requesting LinkCheck and DeviceTime"));
    node.sendMacCommandReq(RADIOLIB_LORAWAN_MAC_LINK_CHECK);
    node.sendMacCommandReq(RADIOLIB_LORAWAN_MAC_DEVICE_TIME);
    state = node.sendReceive(uplinkPayload, sizeof(uplinkPayload), Port, downlinkPayload, &downlinkSize, true, &uplinkDetails, &downlinkDetails);

If remove it (maybe one of them, not 100% sure) all is working fine.

Maybe this could help. The Stack smashing protect failure! is in most cases buffer related (overflow etc.)

THANKS!

2 replies

StevenCellist Mar 31, 2024
Collaborator

Not at the desk during Easter, I hope to give it a shot in a few days. Haven't looked at those functions/commands in a while, maybe something is indeed broken somehow.

HeadBoffin Apr 2, 2024
Collaborator

Maybe this could help. The Stack smashing protect failure! is in most cases buffer related (overflow etc.)

It would be super useful, particularly as it's not related to the ADR discussions, if you could open an issue with the appropriate template. In the meanwhile I'll collate the testing logs on the Reference version.

michapr · 2024-04-02T09:12:33Z

michapr
Apr 2, 2024
Author

ADR-issue is not a real *ADR"-issue, but device is rebooting - opened a new issue as requested: #1049 and close this one.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

LoRaWAN Datarate with ADR (v 6.5.0) #1040

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 8 comments 4 replies

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

LoRaWAN Datarate with ADR (v 6.5.0) #1040

michapr Mar 29, 2024

Replies: 8 comments · 4 replies

StevenCellist Mar 29, 2024 Collaborator

HeadBoffin Mar 29, 2024 Collaborator

michapr Mar 29, 2024 Author

michapr Mar 30, 2024 Author

StevenCellist Mar 30, 2024 Collaborator

michapr Mar 30, 2024 Author

HeadBoffin Mar 30, 2024 Collaborator

michapr Mar 30, 2024 Author

michapr Mar 31, 2024 Author

StevenCellist Mar 31, 2024 Collaborator

HeadBoffin Apr 2, 2024 Collaborator

michapr Apr 2, 2024 Author

michapr
Mar 29, 2024

Replies: 8 comments 4 replies

StevenCellist
Mar 29, 2024
Collaborator

HeadBoffin
Mar 29, 2024
Collaborator

michapr
Mar 29, 2024
Author

michapr
Mar 30, 2024
Author

StevenCellist Mar 30, 2024
Collaborator

michapr
Mar 30, 2024
Author

HeadBoffin Mar 30, 2024
Collaborator

michapr
Mar 30, 2024
Author

michapr
Mar 31, 2024
Author

StevenCellist Mar 31, 2024
Collaborator

HeadBoffin Apr 2, 2024
Collaborator

michapr
Apr 2, 2024
Author