search

jgromes / RadioLib

Universal wireless communication library for embedded devices
https://jgromes.github.io/RadioLib/
MIT License
1.55k stars 387 forks source link

Unable to send multiple LoRaWAN packets #1297

Open alistair23 opened 1 day ago

alistair23 commented 1 day ago

Describe the bug Running using the TockHal on the Apollo3 with a SX126x the first LoRa transmission works, but all subsequent transmits don't work, wither either error -5 (RADIOLIB_ERR_TX_TIMEOUT) or -1108 (RADIOLIB_ERR_UPLINK_UNAVAILABLE).

I am confident it's not a pin out issue as the first operation works and multiple non-LoRaWAN operations also work

Debug mode output

``` [2024-10-30 15:27:37.525] [SX1261] Initialising Radio ... [2024-10-30 15:27:37.528] RLB_DBG: [2024-10-30 15:27:37.528] RadioLib Info [2024-10-30 15:27:37.528] Version: "7.1.0.0" [2024-10-30 15:27:37.531] Platform: "Generic" [2024-10-30 15:27:37.534] Compiled: "Oct 30 2024" "15:26:05" [2024-10-30 15:27:37.547] RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING: [2024-10-30 15:27:37.552] RLB_DBG: 00000320: 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 SX1261 V2D 2D02. [2024-10-30 15:27:37.560] RLB_DBG: [2024-10-30 15:27:37.560] RLB_DBG: M SX126x [2024-10-30 15:27:37.677] RLB_PRO: Setting up fixed channels (subband 2) [2024-10-30 15:27:37.680] RLB_PRO: UL: 8 1 (1717986918 - 1082959462) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.686] RLB_PRO: UL: 9 1 (0 - 1082959872) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.692] RLB_PRO: UL: 10 1 (-1717986918 - 1082960281) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.698] RLB_PRO: UL: 11 1 (858993459 - 1082960691) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.704] RLB_PRO: UL: 12 1 (-858993459 - 1082961100) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.711] RLB_PRO: UL: 13 1 (1717986918 - 1082961510) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.717] RLB_PRO: UL: 14 1 (0 - 1082961920) | DL: 0 5 (0 - 0) [2024-10-30 15:27:37.723] RLB_PRO: UL: 15 1 (-1717986918 - 1082962329) | DL: 0 5 (0 - 0) [2024-10-30 15:27:38.038] RLB_PRO: [MAC] 0x03 [2024-10-30 15:27:38.038] RLB_PRO: 00000000: 20 [2024-10-30 15:27:38.046] RLB_PRO: LinkAdrReq: dataRate = 2, txSteps = 0, nbTrans = 0 [2024-10-30 15:27:38.059] RLB_PRO: LinkAdrAns: 07 [2024-10-30 15:27:38.059] RLB_PRO: [MAC] 0x04 [2024-10-30 15:27:38.062] RLB_PRO: 00000000: 00 . [2024-10-30 15:27:38.071] RLB_PRO: DutyCycleReq: max duty cycle = 1/2^0 [2024-10-30 15:27:38.074] RLB_PRO: [MAC] 0x05 [2024-10-30 15:27:38.076] RLB_PRO: 00000000: 08 68 e2 8c .h.. [2024-10-30 15:27:38.082] RLB_PRO: RXParamSetupReq: Rx1DrOffset = 0, rx2DataRate = 8, freq = [2024-10-30 15:27:38.106] RLB_PRO: [MAC] 0x08 [2024-10-30 15:27:38.106] RLB_PRO: 00000000: 01 . [2024-10-30 15:27:38.114] RLB_PRO: RXTimingSetupReq: delay = 1 sec [2024-10-30 15:27:38.117] RLB_PRO: [MAC] 0x09 [2024-10-30 15:27:38.120] RLB_PRO: 00000000: 1d . [2024-10-30 15:27:38.126] RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 1, maxEirp = 30 dBm [2024-10-30 15:27:38.134] RLB_PRO: [MAC] 0x0c [2024-10-30 15:27:38.134] RLB_PRO: 00000000: 65 e [2024-10-30 15:27:38.143] RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5 [2024-10-30 15:27:38.149] RLB_PRO: [MAC] 0x0f [2024-10-30 15:27:38.149] RLB_PRO: 00000000: fa . [2024-10-30 15:27:38.157] RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10 [2024-10-30 15:27:38.497] RLB_PRO: [2024-10-30 15:27:38.497] RLB_PRO: PHY: Frequency = MHz, TX = 858993459 dBm [2024-10-30 15:27:38.538] RLB_PRO: LoRa: SF = 10, BW = kHz, CR = 4/335452, IQ: [2024-10-30 15:27:38.569] RLB_DBG: Timeout in 1853 ms [2024-10-30 15:27:38.977] RLB_PRO: JoinRequest sent (DevNonce = 0) <-- Rx Delay start [2024-10-30 15:27:38.981] RLB_PRO: 00000000: 00 00 00 00 00 00 00 00 00 59 8a 06 d0 7e d5 b3 .........Y...~.. [2024-10-30 15:27:38.991] RLB_PRO: 00000010: 70 00 00 fa 00 48 33 p....H3 [2024-10-30 15:27:39.020] RLB_PRO: [2024-10-30 15:27:39.020] RLB_PRO: PHY: Frequency = MHz, TX = -858993459 dBm [2024-10-30 15:27:39.061] RLB_PRO: LoRa: SF = 10, BW = kHz, CR = 4/335452, IQ: [2024-10-30 15:27:43.967] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end [2024-10-30 15:27:44.100] RLB_PRO: Closing Rx1 window [2024-10-30 15:27:44.136] RLB_PRO: JoinAccept (JoinNonce = 175, previously 0): [2024-10-30 15:27:44.141] RLB_PRO: 00000000: 20 af 00 00 13 00 00 4c 80 0d 26 88 05 00 ff 00 ......L..&..... [2024-10-30 15:27:44.151] RLB_PRO: 00000010: 00 00 00 00 00 02 00 00 00 00 00 00 01 49 43 c8 .............IC. [2024-10-30 15:27:44.157] RLB_PRO: 00000020: 9e . [2024-10-30 15:27:44.165] RLB_PRO: LoRaWAN revision: 1.1 [2024-10-30 15:27:44.187] RLB_PRO: [MAC] 0x05 [2024-10-30 15:27:44.187] RLB_PRO: 00000000: 08 68 e2 8c .h.. [2024-10-30 15:27:44.196] RLB_PRO: RXParamSetupReq: Rx1DrOffset = 0, rx2DataRate = 8, freq = [2024-10-30 15:27:44.218] RLB_PRO: [MAC] 0x08 [2024-10-30 15:27:44.218] RLB_PRO: 00000000: 05 . [2024-10-30 15:27:44.226] RLB_PRO: RXTimingSetupReq: delay = 5 sec [2024-10-30 15:27:44.229] RLB_PRO: Processing CFList [2024-10-30 15:27:44.232] RLB_PRO: [MAC] 0x03 [2024-10-30 15:27:44.236] RLB_PRO: 00000000: ff 00 ff 00 00 00 00 00 00 02 00 00 00 00 .............. [2024-10-30 15:27:44.242] RLB_PRO: LinkAdrReq: dataRate = 15, txSteps = 15, nbTrans = 0 [2024-10-30 15:27:44.248] RLB_PRO: UL: 8 1 (1717986918 - 1082959462) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.254] RLB_PRO: UL: 9 1 (0 - 1082959872) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.261] RLB_PRO: UL: 10 1 (-1717986918 - 1082960281) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.267] RLB_PRO: UL: 11 1 (858993459 - 1082960691) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.273] RLB_PRO: UL: 12 1 (-858993459 - 1082961100) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.279] RLB_PRO: UL: 13 1 (1717986918 - 1082961510) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.288] RLB_PRO: UL: 14 1 (0 - 1082961920) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.291] RLB_PRO: UL: 15 1 (-1717986918 - 1082962329) | DL: 0 5 (0 - 0) [2024-10-30 15:27:44.297] RLB_PRO: UL: 65 1 (0 - 1082960896) | DL: 6 6 (0 - 0) [2024-10-30 15:27:44.313] RLB_PRO: LinkAdrAns: 07 [2024-10-30 15:27:44.329] success! [2024-10-30 15:27:44.329] [SX1261] Transmitting [2024-10-30 15:27:44.332] RLB_PRO: Uplink MAC payload: [2024-10-30 15:27:44.332] RLB_PRO: 00000000: 0b 01 .. [2024-10-30 15:27:44.658] RLB_PRO: Uplink (FCntUp = 0) decoded: [2024-10-30 15:27:44.662] RLB_PRO: 00000000: 11 00 00 cc 0c 00 00 00 a2 a2 01 00 fc ff ff ff ................ [2024-10-30 15:27:44.669] RLB_PRO: 00000010: 40 4c 80 0d 26 82 00 00 85 35 01 0f f9 bc 3d 47 @L..&....5....=G [2024-10-30 15:27:44.679] RLB_PRO: 00000020: 39 cd 8c 70 03 3e 9..p.> [2024-10-30 15:27:44.733] RLB_PRO: [2024-10-30 15:27:44.733] RLB_PRO: PHY: Frequency = MHz, TX = 1717986918 dBm [2024-10-30 15:27:44.774] RLB_PRO: LoRa: SF = 10, BW = kHz, CR = 4/335452, IQ: [2024-10-30 15:27:44.803] RLB_DBG: Timeout in 1853 ms [2024-10-30 15:27:45.211] RLB_PRO: Uplink sent <-- Rx Delay start [2024-10-30 15:27:45.234] RLB_PRO: [2024-10-30 15:27:45.234] RLB_PRO: PHY: Frequency = MHz, TX = 1717986918 dBm [2024-10-30 15:27:45.275] RLB_PRO: LoRa: SF = 10, BW = kHz, CR = 4/335452, IQ: [2024-10-30 15:27:50.200] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end [2024-10-30 15:27:50.333] RLB_PRO: Closing Rx1 window [2024-10-30 15:27:50.372] RLB_PRO: Downlink (NFCntDown = 0) encoded: [2024-10-30 15:27:50.377] RLB_PRO: 00000000: 49 00 00 00 00 01 4c 80 0d 26 00 00 00 00 00 10 I.....L..&...... [2024-10-30 15:27:50.387] RLB_PRO: 00000010: 60 4c 80 0d 26 88 00 00 fa fb ea e2 6b 2f 4f 40 `L..&.......k/O@ [2024-10-30 15:27:50.393] RLB_PRO: 00000020: 01 b9 7e 21 ..~! [2024-10-30 15:27:50.407] RLB_PRO: [MAC] 0x0b [2024-10-30 15:27:50.407] RLB_PRO: 00000000: 01 . [2024-10-30 15:27:50.415] RLB_PRO: RekeyConf: server version = 1.1 [2024-10-30 15:27:50.418] RLB_PRO: [MAC] 0x03 [2024-10-30 15:27:50.421] RLB_PRO: 00000000: 51 00 ff 00 00 00 00 00 00 00 00 00 00 01 Q............. [2024-10-30 15:27:50.427] RLB_PRO: LinkAdrReq: dataRate = 5, txSteps = 1, nbTrans = 1 [2024-10-30 15:27:50.434] RLB_PRO: UL: 8 1 (1717986918 - 1082959462) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.440] RLB_PRO: UL: 9 1 (0 - 1082959872) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.446] RLB_PRO: UL: 10 1 (-1717986918 - 1082960281) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.452] RLB_PRO: UL: 11 1 (858993459 - 1082960691) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.458] RLB_PRO: UL: 12 1 (-858993459 - 1082961100) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.467] RLB_PRO: UL: 13 1 (1717986918 - 1082961510) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.473] RLB_PRO: UL: 14 1 (0 - 1082961920) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.476] RLB_PRO: UL: 15 1 (-1717986918 - 1082962329) | DL: 0 5 (0 - 0) [2024-10-30 15:27:50.491] RLB_PRO: LinkAdrAns: 07 [2024-10-30 15:27:50.491] RLB_PRO: [MAC] 0x06 [2024-10-30 15:27:50.500] RLB_PRO: DevStatusAns: status = 0xff08 [2024-10-30 15:27:50.503] success! [2024-10-30 15:27:50.503] Waiting 60 minutes before transmitting again [2024-10-30 16:27:49.810] [SX1261] Transmitting [2024-10-30 16:27:49.810] RLB_PRO: Uplink MAC payload: [2024-10-30 16:27:49.813] RLB_PRO: 00000000: 03 07 06 ff 08 ..... [2024-10-30 16:27:50.138] RLB_PRO: Uplink (FCntUp = 1) decoded: [2024-10-30 16:27:50.143] RLB_PRO: 00000000: 49 00 00 00 00 01 4c 80 0d 26 00 00 00 00 00 10 I.....L..&...... [2024-10-30 16:27:50.150] RLB_PRO: 00000010: 40 4c 80 0d 26 85 01 00 6a bd 09 8b cf 01 a7 2c @L..&...j......, [2024-10-30 16:27:50.159] RLB_PRO: 00000020: eb d8 f9 7e a0 01 00 00 00 ...~..... [2024-10-30 16:27:50.214] RLB_PRO: [2024-10-30 16:27:50.214] RLB_PRO: PHY: Frequency = MHz, TX = 1717986918 dBm [2024-10-30 16:27:50.255] RLB_PRO: LoRa: SF = 7, BW = kHz, CR = 4/335452, IQ: [2024-10-30 16:27:50.278] RLB_PRO: Delaying transmission by 597374 ms [2024-10-30 16:37:47.546] RLB_DBG: Timeout in 308 ms [2024-10-30 16:37:47.891] RLB_PRO: Uplink sent <-- Rx Delay start [2024-10-30 16:37:47.896] failed, code -5 [2024-10-30 16:37:47.896] Waiting 60 minutes before transmitting again [2024-10-30 17:37:47.201] [SX1261] Transmitting [2024-10-30 17:37:47.201] RLB_PRO: Uplink MAC payload: [2024-10-30 17:37:47.204] RLB_PRO: 00000000: 03 07 06 ff 08 ..... [2024-10-30 17:37:47.529] RLB_PRO: Uplink (FCntUp = 1) decoded: [2024-10-30 17:37:47.533] RLB_PRO: 00000000: 49 00 00 00 00 00 4c 80 0d 26 01 00 00 00 00 15 I.....L..&...... [2024-10-30 17:37:47.541] RLB_PRO: 00000010: 40 4c 80 0d 26 85 01 00 6a bd 09 8b cf 01 a7 2c @L..&...j......, [2024-10-30 17:37:47.550] RLB_PRO: 00000020: eb d8 f9 7e a0 6b 41 22 ab ...~.kA". [2024-10-30 17:37:47.590] failed, code -1108 [2024-10-30 17:37:47.590] Waiting 60 minutes before transmitting again ```

To Reproduce https://github.com/alistair23/libtock-c/blob/alistair/lora-wan/examples/lora/sensor-lorawan/main.cc#L91

Sketch that is causing the module fail

```c++ int main(void) { CayenneLPP Payload(MAX_SIZE); printf("[SX1261] Initialising Radio ... \r\n"); // create a new instance of the HAL class TockHal* hal = new TockHal(); int state; // now we can create the radio module // pinout corresponds to the SparkFun LoRa Thing Plus - expLoRaBLE // NSS pin: 0 // DIO1 pin: 2 // NRST pin: 4 // BUSY pin: 1 SX1262 tock_module = new Module(hal, RADIO_NSS, RADIO_DIO_1, RADIO_RESET, RADIO_BUSY); LoRaWANNode node(&tock_module, Region, subBand); // Setup the radio // The settings here work for the SparkFun LoRa Thing Plus - expLoRaBLE node.scanGuard = 30; tock_module.XTAL = true; state = tock_module.begin(915.0); if (state != RADIOLIB_ERR_NONE) { printf("begin failed, code %d\r\n", state); return 1; } node.beginOTAA(joinEUI, devEUI, nwkKey, appKey); state = node.activateOTAA(); if (state != RADIOLIB_LORAWAN_NEW_SESSION) { printf("activateOTAA failed, code %d\r\n", state); return 1; } printf("success!\r\n"); hal->detachInterrupt(RADIO_DIO_1); hal->pinMode(RADIO_DIO_1, PIN_INPUT); int temp = 0; int humi = 0; // loop forever for ( ;;) { Payload.reset(); // Read some sensor data from the board libtocksync_temperature_read(&temp); libtocksync_humidity_read(&humi); Payload.addTemperature(0, temp); Payload.addRelativeHumidity(0, humi); printf("[SX1261] Transmitting\r\n"); state = node.sendReceive(Payload.getBuffer(), Payload.getSize()); if (state > 0) { // the packet was successfully transmitted printf("success!\r\n"); } else { printf("failed, code %d\r\n", state); } printf("Waiting 60 minutes before transmitting again\r\n"); for (int i = 0; i < 60; i++) { hal->delay(60 * 1000); } } return 0; } ```

Expected behavior I expect the transmission to complete every 60 minutes, with either no errors or something like -1116.

I also expect to see all of the traffic in TTN, but I'm currently only seeing the first message.

Screenshots If applicable, add screenshots to help explain your problem.

Additional info (please complete):

StevenCellist commented 1 day ago

Library version: 7.2.0

Faster than light?

Does this problem also occur on 7.0.2 and if yes, on the last 6.x version?

alistair23 commented 1 day ago

Ha!

It happens on 7.0.2, I'll have to test on the 6.x version

StevenCellist commented 17 hours ago

To be very clear: it feels like you think you used 7.0.2 for this issue, but your debug output shows 7.1.0 being the version used. Please confirm if the issue exists on all of 7.1.0 (yes, given the log), and 7.0.2, and the last of 6.x.

alistair23 commented 16 hours ago

Same thing on 6.6.0-ish (fffb1fae9f6c43997c7ee0993e68ec7cd80ebb17).

I was origianlly using fffb1fae9f6c43997c7ee0993e68ec7cd80ebb17 as it include some LoRaWAN fixes for some other problems, specifically a custom scanGuard.

[2024-10-30 21:32:27.915] [SX1261] Initialising Radio ... 
[2024-10-30 21:32:27.918] RLB_DBG: 
[2024-10-30 21:32:27.918] RadioLib Info
[2024-10-30 21:32:27.918] Version:  "6.6.0.0"
[2024-10-30 21:32:27.921] Platform: "Generic"
[2024-10-30 21:32:27.924] Compiled: "Oct 30 2024" "21:31:51"
[2024-10-30 21:32:27.938] RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
[2024-10-30 21:32:27.942] RLB_DBG: 0000320 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00 | SX1261 V2D 2D02.
[2024-10-30 21:32:27.950] RLB_DBG: 
[2024-10-30 21:32:27.950] RLB_DBG: M    SX126x
[2024-10-30 21:32:28.067] RLB_PRO: Setting up fixed channels (subband 2)
[2024-10-30 21:32:28.070] RLB_PRO: mask[7] = 0x0002
[2024-10-30 21:32:28.072] RLB_PRO: UL:  65 1  (0 - 1082960896) | DL:   6 6  (0 - 0)
[2024-10-30 21:32:28.078] RLB_PRO: mask[0] = 0xff00
[2024-10-30 21:32:28.078] RLB_PRO: UL:  65 1  (0 - 1082960896) | DL:   6 6  (0 - 0)
[2024-10-30 21:32:28.084] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.090] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.096] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.102] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.108] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.115] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.123] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.127] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:28.442] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:28.442] RLB_PRO: 0000000 20 00 00 80                                     |  ...              
[2024-10-30 21:32:28.450] RLB_PRO: LinkADRReq: dataRate = 2, txSteps = 0, chMask = 0x0000, chMaskCntl = 0, nbTrans = 0
[2024-10-30 21:32:28.462] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:28.465] RLB_PRO: [MAC] 0x04
[2024-10-30 21:32:28.465] RLB_PRO: 0000000 00                                              | .                 
[2024-10-30 21:32:28.473] RLB_PRO: DutyCycleReq: max duty cycle = 1/2^0
[2024-10-30 21:32:28.476] RLB_PRO: [MAC] 0x05
[2024-10-30 21:32:28.479] RLB_PRO: 0000000 08 68 e2 8c                                     | .h..              
[2024-10-30 21:32:28.487] RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 8, freq = 
[2024-10-30 21:32:28.499] RLB_PRO: RXParamSetupAns: status = 0x07
[2024-10-30 21:32:28.502] RLB_PRO: [MAC] 0x08
[2024-10-30 21:32:28.502] RLB_PRO: 0000000 01                                              | .                 
[2024-10-30 21:32:28.510] RLB_PRO: RXTimingSetupReq: delay = 1 sec
[2024-10-30 21:32:28.513] RLB_PRO: [MAC] 0x09
[2024-10-30 21:32:28.516] RLB_PRO: 0000000 1d                                              | .                 
[2024-10-30 21:32:28.525] RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 1, maxEirp = 30 dBm
[2024-10-30 21:32:28.530] RLB_PRO: [MAC] 0x0c
[2024-10-30 21:32:28.530] RLB_PRO: 0000000 65                                              | e                 
[2024-10-30 21:32:28.539] RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
[2024-10-30 21:32:28.545] RLB_PRO: [MAC] 0x0f
[2024-10-30 21:32:28.545] RLB_PRO: 0000000 fa                                              | .                 
[2024-10-30 21:32:28.554] RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
[2024-10-30 21:32:28.559] RLB_PRO: RejoinParamSetupAns: status = 0x03
[2024-10-30 21:32:28.871] RLB_PRO: 
[2024-10-30 21:32:28.871] RLB_PRO: PHY: Frequency UL =  MHz
[2024-10-30 21:32:28.908] RLB_PRO: PHY: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-30 21:32:28.950] RLB_DBG: Timeout in 1853 ms
[2024-10-30 21:32:29.356] RLB_PRO: JoinRequest sent (DevNonce = 0) <-- Rx Delay start
[2024-10-30 21:32:29.359] RLB_PRO: 
[2024-10-30 21:32:29.361] RLB_PRO: PHY: Frequency DL =  MHz
[2024-10-30 21:32:29.398] RLB_PRO: PHY: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-30 21:32:34.344] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end 
[2024-10-30 21:32:34.477] RLB_PRO: Closing Rx1 window
[2024-10-30 21:32:34.523] RLB_PRO: JoinAccept (JoinNonce = 177, previously 0):
[2024-10-30 21:32:34.527] RLB_PRO: 0000000 20 b1 00 00 13 00 00 79 95 0d 26 88 05 00 ff 00 |  ......y..&.....
[2024-10-30 21:32:34.537] RLB_PRO: 0000010 00 00 00 00 00 02 00 00 00 00 00 00 01 64 e6 72 | .............d.r
[2024-10-30 21:32:34.543] RLB_PRO: 0000020 e2                                              | .                 
[2024-10-30 21:32:34.552] RLB_PRO: LoRaWAN revision: 1.1
[2024-10-30 21:32:34.572] RLB_PRO: [MAC] 0x05
[2024-10-30 21:32:34.572] RLB_PRO: 0000000 08 68 e2 8c                                     | .h..              
[2024-10-30 21:32:34.581] RLB_PRO: RXParamSetupReq: rx1DrOffset = 0, rx2DataRate = 8, freq = 
[2024-10-30 21:32:34.598] RLB_PRO: RXParamSetupAns: status = 0x07
[2024-10-30 21:32:34.601] RLB_PRO: [MAC] 0x08
[2024-10-30 21:32:34.601] RLB_PRO: 0000000 05                                              | .                 
[2024-10-30 21:32:34.609] RLB_PRO: RXTimingSetupReq: delay = 5 sec
[2024-10-30 21:32:34.612] RLB_PRO: Processing CFList
[2024-10-30 21:32:34.615] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:34.618] RLB_PRO: 0000000 ff 00 ff 00                                     | ....              
[2024-10-30 21:32:34.627] RLB_PRO: LinkADRReq: dataRate = 15, txSteps = 15, chMask = 0xff00, chMaskCntl = 0, nbTrans = 0
[2024-10-30 21:32:34.633] RLB_PRO: ADR mask: clearing channels
[2024-10-30 21:32:34.639] RLB_PRO: mask[0] = 0xff00
[2024-10-30 21:32:34.639] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.647] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.651] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.657] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.666] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.672] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.678] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.684] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.690] RLB_PRO: Saving mask to ULChannels[0]:
[2024-10-30 21:32:34.693] RLB_PRO: 0000000 ff 00 ff 01                                     | ....              
[2024-10-30 21:32:34.702] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:34.705] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:34.705] RLB_PRO: 0000000 ff 00 00 10                                     | ....              
[2024-10-30 21:32:34.713] RLB_PRO: LinkADRReq: dataRate = 15, txSteps = 15, chMask = 0x0000, chMaskCntl = 1, nbTrans = 0
[2024-10-30 21:32:34.722] RLB_PRO: mask[1] = 0x0000
[2024-10-30 21:32:34.725] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.731] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.737] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.743] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.749] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.755] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.761] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.767] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.773] RLB_PRO: Saving mask to ULChannels[4]:
[2024-10-30 21:32:34.776] RLB_PRO: 0000000 ff 00 00 11                                     | ....              
[2024-10-30 21:32:34.785] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:34.788] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:34.791] RLB_PRO: 0000000 ff 00 00 20                                     | ...               
[2024-10-30 21:32:34.797] RLB_PRO: LinkADRReq: dataRate = 15, txSteps = 15, chMask = 0x0000, chMaskCntl = 2, nbTrans = 0
[2024-10-30 21:32:34.805] RLB_PRO: mask[2] = 0x0000
[2024-10-30 21:32:34.808] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.814] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.820] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.826] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.832] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.838] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.844] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.851] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.856] RLB_PRO: Saving mask to ULChannels[8]:
[2024-10-30 21:32:34.863] RLB_PRO: 0000000 ff 00 00 21                                     | ...!              
[2024-10-30 21:32:34.868] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:34.871] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:34.874] RLB_PRO: 0000000 ff 00 00 30                                     | ...0              
[2024-10-30 21:32:34.883] RLB_PRO: LinkADRReq: dataRate = 15, txSteps = 15, chMask = 0x0000, chMaskCntl = 3, nbTrans = 0
[2024-10-30 21:32:34.891] RLB_PRO: mask[3] = 0x0000
[2024-10-30 21:32:34.891] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.900] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.903] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.912] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.918] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.924] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.931] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.937] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.942] RLB_PRO: Saving mask to ULChannels[12]:
[2024-10-30 21:32:34.946] RLB_PRO: 0000000 ff 00 00 31                                     | ...1              
[2024-10-30 21:32:34.954] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:34.957] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:34.957] RLB_PRO: 0000000 ff 02 00 40                                     | ...@              
[2024-10-30 21:32:34.966] RLB_PRO: LinkADRReq: dataRate = 15, txSteps = 15, chMask = 0x0002, chMaskCntl = 4, nbTrans = 0
[2024-10-30 21:32:34.975] RLB_PRO: mask[4] = 0x0002
[2024-10-30 21:32:34.977] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.984] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.990] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:34.996] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:35.002] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:35.008] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:35.014] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:35.020] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:35.026] RLB_PRO: UL:  65 1  (0 - 1082960896) | DL:   6 6  (0 - 0)
[2024-10-30 21:32:35.032] RLB_PRO: Saving mask to ULChannels[16]:
[2024-10-30 21:32:35.035] RLB_PRO: 0000000 ff 02 00 41                                     | ...A              
[2024-10-30 21:32:35.044] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:35.064] success!
[2024-10-30 21:32:35.064] [SX1261] Transmitting
[2024-10-30 21:32:35.372] RLB_PRO: 
[2024-10-30 21:32:35.372] RLB_PRO: PHY: Frequency UL =  MHz
[2024-10-30 21:32:35.409] RLB_PRO: PHY: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-30 21:32:35.434] RLB_PRO: Uplink MAC payload (1 commands):
[2024-10-30 21:32:35.437] RLB_PRO: 0000000 0b 01                                           | ..                
[2024-10-30 21:32:35.454] RLB_PRO: Uplink (FCntUp = 0) decoded:
[2024-10-30 21:32:35.458] RLB_PRO: 0000000 11 00 00 00 0c 00 00 00 a2 a2 01 00 fc ff ff ff | ................
[2024-10-30 21:32:35.465] RLB_PRO: 0000010 40 79 95 0d 26 82 00 00 98 04 01 44 d1 a5 44 43 | @y..&......D..DC
[2024-10-30 21:32:35.475] RLB_PRO: 0000020 ca 60 8c 70 03 3e                               | .`.p.>            
[2024-10-30 21:32:35.519] RLB_DBG: Timeout in 1853 ms
[2024-10-30 21:32:35.925] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-30 21:32:35.930] RLB_PRO: 
[2024-10-30 21:32:35.930] RLB_PRO: PHY: Frequency DL =  MHz
[2024-10-30 21:32:35.968] RLB_PRO: PHY: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-30 21:32:40.912] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end 
[2024-10-30 21:32:41.045] RLB_PRO: Closing Rx1 window
[2024-10-30 21:32:41.093] RLB_PRO: Downlink (NFCntDown = 0) encoded:
[2024-10-30 21:32:41.097] RLB_PRO: 0000000 49 00 00 00 00 01 79 95 0d 26 00 00 00 00 00 0f | I.....y..&......
[2024-10-30 21:32:41.105] RLB_PRO: 0000010 60 79 95 0d 26 87 00 00 4d f2 cd 17 5a 00 fe 3c | `y..&...M...Z..<
[2024-10-30 21:32:41.114] RLB_PRO: 0000020 1f 26 d1                                        | .&.               
[2024-10-30 21:32:41.127] RLB_PRO: [MAC] 0x0b
[2024-10-30 21:32:41.127] RLB_PRO: 0000000 01                                              | .                 
[2024-10-30 21:32:41.135] RLB_PRO: RekeyConf: server version = 1.1
[2024-10-30 21:32:41.138] RLB_PRO: [MAC] 0x03
[2024-10-30 21:32:41.141] RLB_PRO: 0000000 51 00 ff 01                                     | Q...              
[2024-10-30 21:32:41.147] RLB_PRO: LinkADRReq: dataRate = 5, txSteps = 1, chMask = 0xff00, chMaskCntl = 0, nbTrans = 1
[2024-10-30 21:32:41.160] RLB_PRO: ADR mask: clearing channels
[2024-10-30 21:32:41.163] RLB_PRO: mask[0] = 0xff00
[2024-10-30 21:32:41.163] RLB_PRO: UL:   8 1  (1610612736 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.172] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.175] RLB_PRO: UL:  10 1  (-1610612736 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.184] RLB_PRO: UL:  11 1  (1073741824 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.190] RLB_PRO: UL:  12 1  (-536870912 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.196] RLB_PRO: UL:  13 1  (1610612736 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.202] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.208] RLB_PRO: UL:  15 1  (-1610612736 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-30 21:32:41.214] RLB_PRO: Saving mask to ULChannels[0]:
[2024-10-30 21:32:41.217] RLB_PRO: 0000000 ff 00 ff 01                                     | ....              
[2024-10-30 21:32:41.226] RLB_PRO: LinkADRAns: status = 0x07
[2024-10-30 21:32:41.229] success!
[2024-10-30 21:32:41.229] Waiting 60 minutes before transmitting again
[2024-10-30 22:32:40.532] [SX1261] Transmitting
[2024-10-30 22:32:40.838] RLB_PRO: 
[2024-10-30 22:32:40.838] RLB_PRO: PHY: Frequency UL =  MHz
[2024-10-30 22:32:40.876] RLB_PRO: PHY: SF = 7, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-30 22:32:40.900] RLB_PRO: Uplink MAC payload (1 commands):
[2024-10-30 22:32:40.904] RLB_PRO: 0000000 03 07                                           | ..                
[2024-10-30 22:32:40.919] RLB_PRO: Uplink (FCntUp = 1) decoded:
[2024-10-30 22:32:40.924] RLB_PRO: 0000000 11 00 00 00 0c 00 00 00 a2 a2 01 00 fc ff ff ff | ................
[2024-10-30 22:32:40.932] RLB_PRO: 0000010 40 79 95 0d 26 82 01 00 6f 17 01 38 20 15 ae 74 | @y..&...o..8 ..t
[2024-10-30 22:32:40.941] RLB_PRO: 0000020 25 4d d1 00 50 00                               | %M..P.            
[2024-10-30 22:32:40.985] RLB_DBG: Timeout in 282 ms
[2024-10-30 22:32:41.300] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-30 22:32:41.305] failed, code -5

...

[2024-10-31 03:32:40.814] [SX1261] Transmitting
[2024-10-31 03:32:41.120] RLB_PRO: 
[2024-10-31 03:32:41.120] RLB_PRO: PHY: Frequency UL =  MHz
[2024-10-31 03:32:41.157] RLB_PRO: PHY: SF = 7, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 03:32:41.186] RLB_PRO: Uplink (FCntUp = 1) decoded:
[2024-10-31 03:32:41.190] RLB_PRO: 0000000 11 00 00 00 0c 00 00 00 a2 a2 01 00 fc ff ff ff | ................
[2024-10-31 03:32:41.198] RLB_PRO: 0000010 40 79 95 0d 26 80 01 00 01 38 20 15 ae 74 25 4d | @y..&....8 ..t%M
[2024-10-31 03:32:41.207] RLB_PRO: 0000020 a9 86 48 34                                     | ..H4              
[2024-10-31 03:32:41.244] RLB_DBG: Timeout in 282 ms
[2024-10-31 03:32:41.558] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-31 03:32:41.563] failed, code -5
[2024-10-31 03:32:41.563] Waiting 60 minutes before transmitting again
[2024-10-31 04:32:40.865] [SX1261] Transmitting
[2024-10-31 04:32:41.171] RLB_PRO: 
[2024-10-31 04:32:41.171] RLB_PRO: PHY: Frequency UL =  MHz
[2024-10-31 04:32:41.208] RLB_PRO: PHY: SF = 7, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 04:32:41.236] RLB_PRO: Uplink (FCntUp = 1) decoded:
[2024-10-31 04:32:41.241] RLB_PRO: 0000000 11 00 00 00 0c 00 00 00 a2 a2 01 00 fc ff ff ff | ................
[2024-10-31 04:32:41.248] RLB_PRO: 0000010 40 79 95 0d 26 80 01 00 01 38 20 15 ae 74 25 4d | @y..&....8 ..t%M
[2024-10-31 04:32:41.257] RLB_PRO: 0000020 97 63 48 34                                     | .cH4              
[2024-10-31 04:32:41.294] RLB_DBG: Timeout in 282 ms
[2024-10-31 04:32:41.608] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-31 04:32:41.614] failed, code -5
[2024-10-31 04:32:41.614] Waiting 60 minutes before transmitting again
[2024-10-31 05:32:40.913] [SX1261] Transmitting
[2024-10-31 05:32:40.913] failed, code -1108
[2024-10-31 05:32:40.916] Waiting 60 minutes before transmitting again
[2024-10-31 06:32:40.215] [SX1261] Transmitting
[2024-10-31 06:32:40.215] failed, code -1108
alistair23 commented 14 hours ago

Same with 7.0.2

[2024-10-31 08:52:41.902] [SX1261] Initialising Radio ... 
[2024-10-31 08:52:41.906] RLB_DBG: 
[2024-10-31 08:52:41.906] RadioLib Info
[2024-10-31 08:52:41.906] Version:  "7.0.2.0"
[2024-10-31 08:52:41.908] Platform: "Generic"
[2024-10-31 08:52:41.911] Compiled: "Oct 31 2024" "08:51:34"
[2024-10-31 08:52:41.925] RLB_DBG: Found SX126x: RADIOLIB_SX126X_REG_VERSION_STRING:
[2024-10-31 08:52:41.930] RLB_DBG: 00000320: 53 58 31 32 36 31 20 56 32 44 20 32 44 30 32 00  SX1261 V2D 2D02.
[2024-10-31 08:52:41.938] RLB_DBG: 
[2024-10-31 08:52:41.938] RLB_DBG: M    SX126x
[2024-10-31 08:52:42.054] RLB_PRO: Setting up fixed channels (subband 2)
[2024-10-31 08:52:42.057] RLB_PRO: UL:   8 1  (1717986918 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.063] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.069] RLB_PRO: UL:  10 1  (-1717986918 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.076] RLB_PRO: UL:  11 1  (858993459 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.082] RLB_PRO: UL:  12 1  (-858993459 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.088] RLB_PRO: UL:  13 1  (1717986918 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.094] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.100] RLB_PRO: UL:  15 1  (-1717986918 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.106] RLB_PRO: UL:   8 1  (1717986918 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.112] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.118] RLB_PRO: UL:  10 1  (-1717986918 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.125] RLB_PRO: UL:  11 1  (858993459 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.131] RLB_PRO: UL:  12 1  (-858993459 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.137] RLB_PRO: UL:  13 1  (1717986918 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.143] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.149] RLB_PRO: UL:  15 1  (-1717986918 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:42.464] RLB_PRO: [MAC] 0x03
[2024-10-31 08:52:42.464] RLB_PRO: 00000000: 20                                                                 
[2024-10-31 08:52:42.472] RLB_PRO: LinkAdrReq: dataRate = 2, txSteps = 0, nbTrans = 0
[2024-10-31 08:52:42.483] RLB_PRO: LinkAdrAns: 07
[2024-10-31 08:52:42.483] RLB_PRO: [MAC] 0x04
[2024-10-31 08:52:42.486] RLB_PRO: 00000000: 00                                               .                 
[2024-10-31 08:52:42.495] RLB_PRO: DutyCycleReq: max duty cycle = 1/2^0
[2024-10-31 08:52:42.498] RLB_PRO: [MAC] 0x05
[2024-10-31 08:52:42.501] RLB_PRO: 00000000: 08 68 e2 8c                                      .h..              
[2024-10-31 08:52:42.507] RLB_PRO: RXParamSetupReq: Rx1DrOffset = 0, rx2DataRate = 8, freq = 
[2024-10-31 08:52:42.528] RLB_PRO: [MAC] 0x08
[2024-10-31 08:52:42.528] RLB_PRO: 00000000: 01                                               .                 
[2024-10-31 08:52:42.536] RLB_PRO: RXTimingSetupReq: delay = 1 sec
[2024-10-31 08:52:42.539] RLB_PRO: [MAC] 0x09
[2024-10-31 08:52:42.542] RLB_PRO: 00000000: 1d                                               .                 
[2024-10-31 08:52:42.548] RLB_PRO: TxParamSetupReq: dlDwell = 0, ulDwell = 1, maxEirp = 30 dBm
[2024-10-31 08:52:42.557] RLB_PRO: [MAC] 0x0c
[2024-10-31 08:52:42.557] RLB_PRO: 00000000: 65                                               e                 
[2024-10-31 08:52:42.565] RLB_PRO: ADRParamSetupReq: limitExp = 6, delayExp = 5
[2024-10-31 08:52:42.571] RLB_PRO: [MAC] 0x0f
[2024-10-31 08:52:42.571] RLB_PRO: 00000000: fa                                               .                 
[2024-10-31 08:52:42.579] RLB_PRO: RejoinParamSetupReq: maxTime = 15, maxCount = 10
[2024-10-31 08:52:42.917] RLB_PRO: 
[2024-10-31 08:52:42.917] RLB_PRO: PHY:  Frequency UL =  MHz
[2024-10-31 08:52:42.957] RLB_PRO: LoRa: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 08:52:42.987] RLB_DBG: Timeout in 1853 ms
[2024-10-31 08:52:43.393] RLB_PRO: JoinRequest sent (DevNonce = 0) <-- Rx Delay start
[2024-10-31 08:52:43.397] RLB_PRO: 00000000: 00 00 00 00 00 00 00 00 00 59 8a 06 d0 7e d5 b3  .........Y...~..
[2024-10-31 08:52:43.407] RLB_PRO: 00000010: 70 00 00 fa 00 48 33                             p....H3           
[2024-10-31 08:52:43.431] RLB_PRO: 
[2024-10-31 08:52:43.431] RLB_PRO: PHY:  Frequency DL =  MHz
[2024-10-31 08:52:43.471] RLB_PRO: LoRa: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 08:52:48.381] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end 
[2024-10-31 08:52:48.514] RLB_PRO: Closing Rx1 window
[2024-10-31 08:52:48.550] RLB_PRO: JoinAccept (JoinNonce = 179, previously 0):
[2024-10-31 08:52:48.555] RLB_PRO: 00000000: 20 b3 00 00 13 00 00 23 f6 0d 26 88 05 00 ff 00   ......#..&.....
[2024-10-31 08:52:48.565] RLB_PRO: 00000010: 00 00 00 00 00 02 00 00 00 00 00 00 01 77 46 3c  .............wF<
[2024-10-31 08:52:48.571] RLB_PRO: 00000020: cf                                               .                 
[2024-10-31 08:52:48.579] RLB_PRO: LoRaWAN revision: 1.1
[2024-10-31 08:52:48.601] RLB_PRO: [MAC] 0x05
[2024-10-31 08:52:48.601] RLB_PRO: 00000000: 08 68 e2 8c                                      .h..              
[2024-10-31 08:52:48.609] RLB_PRO: RXParamSetupReq: Rx1DrOffset = 0, rx2DataRate = 8, freq = 
[2024-10-31 08:52:48.630] RLB_PRO: [MAC] 0x08
[2024-10-31 08:52:48.630] RLB_PRO: 00000000: 05                                               .                 
[2024-10-31 08:52:48.638] RLB_PRO: RXTimingSetupReq: delay = 5 sec
[2024-10-31 08:52:48.641] RLB_PRO: Processing CFList
[2024-10-31 08:52:48.644] RLB_PRO: [MAC] 0x03
[2024-10-31 08:52:48.648] RLB_PRO: 00000000: ff 00 ff 00 00 00 00 00 00 02 00 00 00 00        ..............    
[2024-10-31 08:52:48.654] RLB_PRO: LinkAdrReq: dataRate = 15, txSteps = 15, nbTrans = 0
[2024-10-31 08:52:48.660] RLB_PRO: UL:   8 1  (1717986918 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.666] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.672] RLB_PRO: UL:  10 1  (-1717986918 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.678] RLB_PRO: UL:  11 1  (858993459 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.685] RLB_PRO: UL:  12 1  (-858993459 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.691] RLB_PRO: UL:  13 1  (1717986918 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.700] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.703] RLB_PRO: UL:  15 1  (-1717986918 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:48.709] RLB_PRO: UL:  65 1  (0 - 1082960896) | DL:   6 6  (0 - 0)
[2024-10-31 08:52:48.722] RLB_PRO: LinkAdrAns: 07
[2024-10-31 08:52:48.738] success!
[2024-10-31 08:52:48.738] [SX1261] Transmitting
[2024-10-31 08:52:48.741] RLB_PRO: Uplink MAC payload:
[2024-10-31 08:52:48.741] RLB_PRO: 00000000: 0b 01                                            ..                
[2024-10-31 08:52:49.066] RLB_PRO: Uplink (FCntUp = 0) decoded:
[2024-10-31 08:52:49.070] RLB_PRO: 00000000: 11 00 00 cc 0c 00 00 00 a2 a2 01 00 fc ff ff ff  ................
[2024-10-31 08:52:49.077] RLB_PRO: 00000010: 40 23 f6 0d 26 82 00 00 5e f1 01 b7 91 6f cd 87  @#..&...^....o..
[2024-10-31 08:52:49.087] RLB_PRO: 00000020: ff 1e 8c 70 03 3e                                ...p.>            
[2024-10-31 08:52:49.139] RLB_PRO: 
[2024-10-31 08:52:49.139] RLB_PRO: PHY:  Frequency UL =  MHz
[2024-10-31 08:52:49.178] RLB_PRO: LoRa: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 08:52:49.206] RLB_DBG: Timeout in 1853 ms
[2024-10-31 08:52:49.612] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-31 08:52:49.633] RLB_PRO: 
[2024-10-31 08:52:49.633] RLB_PRO: PHY:  Frequency DL =  MHz
[2024-10-31 08:52:49.673] RLB_PRO: LoRa: SF = 10, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 08:52:54.601] RLB_PRO: Opening Rx1 window (126 ms timeout)... <-- Rx Delay end 
[2024-10-31 08:52:54.734] RLB_PRO: Closing Rx1 window
[2024-10-31 08:52:54.773] RLB_PRO: Downlink (NFCntDown = 0) encoded:
[2024-10-31 08:52:54.778] RLB_PRO: 00000000: 49 00 00 00 00 01 23 f6 0d 26 00 00 00 00 00 0f  I.....#..&......
[2024-10-31 08:52:54.788] RLB_PRO: 00000010: 60 23 f6 0d 26 87 00 00 84 5d 74 0d 5a 8d 59 a0  `#..&....]t.Z.Y.
[2024-10-31 08:52:54.794] RLB_PRO: 00000020: ce bf 64                                         ..d               
[2024-10-31 08:52:54.807] RLB_PRO: [MAC] 0x0b
[2024-10-31 08:52:54.807] RLB_PRO: 00000000: 01                                               .                 
[2024-10-31 08:52:54.816] RLB_PRO: RekeyConf: server version = 1.1
[2024-10-31 08:52:54.819] RLB_PRO: [MAC] 0x03
[2024-10-31 08:52:54.822] RLB_PRO: 00000000: 51 00 ff 00 00 00 00 00 00 00 00 00 00 01        Q.............    
[2024-10-31 08:52:54.828] RLB_PRO: LinkAdrReq: dataRate = 5, txSteps = 1, nbTrans = 1
[2024-10-31 08:52:54.834] RLB_PRO: UL:   8 1  (1717986918 - 1082959462) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.840] RLB_PRO: UL:   9 1  (0 - 1082959872) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.846] RLB_PRO: UL:  10 1  (-1717986918 - 1082960281) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.852] RLB_PRO: UL:  11 1  (858993459 - 1082960691) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.858] RLB_PRO: UL:  12 1  (-858993459 - 1082961100) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.867] RLB_PRO: UL:  13 1  (1717986918 - 1082961510) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.873] RLB_PRO: UL:  14 1  (0 - 1082961920) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.877] RLB_PRO: UL:  15 1  (-1717986918 - 1082962329) | DL:   0 5  (0 - 0)
[2024-10-31 08:52:54.886] RLB_PRO: UL:  65 1  (0 - 1082960896) | DL:   6 6  (0 - 0)
[2024-10-31 08:52:54.895] RLB_PRO: LinkAdrAns: 07
[2024-10-31 08:52:54.895] failed, code 1

[ This one actually worked, the return values changed]

[2024-10-31 08:52:54.898] Waiting 60 minutes before transmitting again
[2024-10-31 09:52:54.198] [SX1261] Transmitting
[2024-10-31 09:52:54.198] RLB_PRO: Uplink MAC payload:
[2024-10-31 09:52:54.201] RLB_PRO: 00000000: 03 07                                            ..                
[2024-10-31 09:52:54.525] RLB_PRO: Uplink (FCntUp = 1) decoded:
[2024-10-31 09:52:54.529] RLB_PRO: 00000000: 49 00 00 00 00 01 23 f6 0d 26 00 00 00 00 00 0f  I.....#..&......
[2024-10-31 09:52:54.537] RLB_PRO: 00000010: 40 23 f6 0d 26 82 01 00 db aa 01 05 c8 7c 09 b1  @#..&........|..
[2024-10-31 09:52:54.545] RLB_PRO: 00000020: ac 13 64 00 44 01                                ..d.D.            
[2024-10-31 09:52:54.598] RLB_PRO: 
[2024-10-31 09:52:54.598] RLB_PRO: PHY:  Frequency UL =  MHz
[2024-10-31 09:52:54.637] RLB_PRO: LoRa: SF = 7, TX = 22 dBm, BW =  kHz, CR = 4/0
[2024-10-31 09:52:54.660] RLB_PRO: Delaying transmission by 597393 ms
[2024-10-31 10:02:51.946] RLB_DBG: Timeout in 282 ms
[2024-10-31 10:02:52.259] RLB_PRO: Uplink sent <-- Rx Delay start
[2024-10-31 10:02:52.265] failed, code -5

[This one also worked, TTN sees the data]

[2024-10-31 10:02:52.265] Waiting 60 minutes before transmitting again
[2024-10-31 11:02:51.567] [SX1261] Transmitting
[2024-10-31 11:02:51.567] RLB_PRO: Uplink MAC payload:
[2024-10-31 11:02:51.570] RLB_PRO: 00000000: 03 07                                            ..                
[2024-10-31 11:02:51.894] RLB_PRO: Uplink (FCntUp = 1) decoded:
[2024-10-31 11:02:51.899] RLB_PRO: 00000000: 49 00 00 00 00 00 23 f6 0d 26 01 00 00 00 00 12  I.....#..&......
[2024-10-31 11:02:51.906] RLB_PRO: 00000010: 40 23 f6 0d 26 82 01 00 db aa 01 05 c8 7c 09 b1  @#..&........|..
[2024-10-31 11:02:51.915] RLB_PRO: 00000020: ac 13 10 e1 2f b6                                ..../.            
[2024-10-31 11:02:51.954] failed, code -1108
[2024-10-31 11:02:51.954] Waiting 60 minutes before transmitting again
StevenCellist commented 8 hours ago

Given that this problem persists across all three versions, and 6.6.0 and 7.0.2 haven't been reported by anyone else to result in this behaviour, I'm very much tempted to say this is a Tock issue. My primary suspect would be your HAL, more specifically the clock-stuff, as I see this line: 

[2024-10-31 09:52:54.660] RLB_PRO: Delaying transmission by 597393 ms
[2024-10-31 10:02:51.946] RLB_DBG: Timeout in 282 ms

Maybe overflow of values? If that is the case, we might get away with a different way of handling clock values within the LoRaWAN stack, but before that, you'll need to investigate the cause of these weird values.

alistair23 commented 5 hours ago

I suspect you are right about it being a timing issue. It seems like the TX window for the subsequent transmits are too low.

What is a usual value of Delaying transmission?

It looks like the getTimeOnAir() values could be too low

For the working case in getTimeOnAir() I am seeing values like this

spreadingFactor: 10
symbolLength_us: 8192
N_symbol_header: 20

while the second attempt is

spreadingFactor: 7
symbolLength_us: 1024
N_symbol_header: 20

which results in a much shorter window

StevenCellist commented 4 hours ago

Let's take RadioLib 7.1 as the go-to version as that is the currently active one.

Transmission delays should not occur under normal circumstances - it can be used by scheduleTransmission() which pretty much no-one should use. The reason why that text would occur is that this->tUplink is apparently larger than tNow:

https://github.com/jgromes/RadioLib/blob/4564d87721997917c567f75c2078106ee92e757a/src/protocols/LoRaWAN/LoRaWAN.cpp#L925-L931

This would suggest to me that somehow tNow has dropped to a lower value than tUplink because of an overflow or something along those lines. So please investigate that before going into Time-on-Air stuff - RadioLib does a clean 5x ToA timeout which has never been a problem.

Also worth investigating is the use of interrupts - notably the STM32Cube I've been working on doesn't handle that very well. IRQs are weird.