search

helium / router

router combines a LoRaWAN Network Server with an API for console, and provides a proxy to the Helium blockchain
Apache License 2.0
70 stars 31 forks source link

Downlinks are not properly sent (wrong timings and RX1 channel) #891

Open Oliv4945 opened 1 year ago

Oliv4945 commented 1 year ago

Describe the bug The downlink is refused by the gateway because it arrives too late, and RX1 does not use a correct tmst value, nor RX1 frequency.

To Reproduce

  1. Reported from an EU868 data only gateway, helium_gateway v1.0.0-alpha.31, asserted in France
  2. Connected to Semtech pico gateway thanks to picoGW_packet_forwarder v.0.1.0
  3. The device uplinks/downlinks was working fine few month ago with another gateway which is know down.
  4. The device RxDelay is set to 4
  5. The network server tries to send an ADRReq to the device:

image

  1. The packet forwarder reports

Uplink:

INFO: Received pkt from mote: 48000000 (fcnt=18893)
JSON up: {"rxpk":[{"tmst":2597889415,"chan":1,"rfch":1,"freq":868.300000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":-5.2,"rssi":-107,"size":16,"data":"QAAAAEiAzUkC/eZOUR/hwQ=="}]}
INFO: [up] PUSH_ACK received in 0 ms

Downlink:

JSON down: {"txpk":{"imme":false,"tmst":2602889415,"freq":869.5250244140625,"rfch":0,"powe":14,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"prea":null,"size":17,"data":"YAAAAEiFfDIDMP8AAAtc/ik="}}
src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=2981758355, packet=2602889415, type=0)
ERROR: Packet REJECTED (jit error=2)
INFO: [down] PULL_RESP received  - token[140:35] :)

(correct downlink as the FCnt is 12924 as reported in the Console)

  1. gateway-rs reports:

Uplink:

Dec 13 13:34:28 grog helium_gateway[880587]: uplink @2597889415 us, 868.30 MHz, Ok(DataRate(SF12, BW125)), snr: -5.2, rssi: -107, len: 16 from 30:37:34:32:48:00:6C:00, module: gateway

Downlink:

Dec 13 13:39:29 grog helium_gateway[880587]: rx1 downlink @2602889415 us, 869.53 MHz, DataRate(SF12, BW125), len: 17 via 30:37:34:32:48:00:6C:00, module: gateway
Dec 13 13:39:29 grog helium_gateway[880587]: rx2 downlink @2602889415 us, 869.53 MHz, DataRate(SF12, BW125), len: 17 via 30:37:34:32:48:00:6C:00, module: gateway

Expected behavior

  1. The rx1 downlink should be on frequency 868.30, not 868.525 MHz
  2. The rx1 and rx2 downlinks should not have the same tmst (SX130x internal counter) value
  3. As rx_tmst - tx_tmst= 5 sec, I guess that RX2 is correct but not RX1
  4. Despite parameters for RX2 being correct, the downlink command arrives far after the RX windows expiration:

Device Info (please complete the following information):

Full logs, both are starting approximately at the same time: 221213 rx_issue_logs.zip

lthiery commented 1 year ago

@mikev might want to take a look at this

mikev commented 1 year ago

The behavior is likely related to this issue & PR Issue - https://github.com/helium/router/issues/423 PR - https://github.com/helium/router/pull/442/files

Oliv4945 commented 1 year ago

@mikev I think that there is actually two issues here:

  1. The incorrect RX1 parameters, which might be related to your changes
  2. The timings, if you look at my initial post the downlink is reported 5 minutes after the uplink. I have few more examples of this:
JSON up: {"rxpk":[{"tmst":840299123,"chan":6,"rfch":0,"freq":867.700000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":10.0,"rssi":-64,"size":23,"data":"ABERERERERERIUNlh3hWNBLpuPPh6FI="}]}

JSON down: {"txpk":{"imme":false,"tmst":845299123,"freq":867.7000122070312,"rfch":0,"powe":14,"modu":"LORA","datr":"SF7BW125","codr":"4/5","ipol":true,"prea":null,"size":17,"data":"IL8kKXZrscfnawrD+L5xxrY="}}
src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=3631201118, packet=845299123, type=0)
ERROR: Packet REJECTED (jit error=2)
INFO: host/sx1301 time offset=(1671005464s:817251µs) - drift=-15µs

Dec 14 10:02:35 grog helium_gateway[880587]: uplink @840299123 us, 867.70 MHz, Ok(DataRate(SF7, BW125)), snr: 10, rssi: -64, len: 23 from 30:37:34:32:48:00:6C:00, module: gateway
Dec 14 10:07:35 grog helium_gateway[880587]: rx1 downlink @845299123 us, 867.70 MHz, DataRate(SF7, BW125), len: 17 via 30:37:34:32:48:00:6C:00, module: gateway

=========================================
JSON up: {"rxpk":[{"tmst":2424775723,"chan":2,"rfch":1,"freq":868.500000,"stat":1,"modu":"LORA","datr":"SF12BW12        5","codr":"4/5","lsnr":-2.2,"rssi":-99,"size":16,"data":"QAAAAEiATkoCiTNTz9O3nA=="}]}
 122519 INFO: [up] PUSH_ACK received in 0 ms

JSON down: {"txpk":{"imme":false,"tmst":2429775723,"freq":869.5250244140625,"rfch":0,"powe":14,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"prea":null,"size":17,"data":"YAAAAEiFxzIDQP8AACcFbVE="}}
src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=3784469599, packet=2429775723, type=0)
ERROR: Packet REJECTED (jit error=2)

Dec 14 11:16:58 grog helium_gateway[1199527]: uplink @2424775723 us, 868.50 MHz, Ok(DataRate(SF12, BW125)), snr: -2.2, rssi: -99, len: 16 from 30:37:34:32:48:00:6C:00, module: gateway

Dec 14 11:21:43 grog helium_gateway[1199527]: rx1 downlink @2429775723 us, 869.53 MHz, 
Dec 14 11:21:48 grog helium_gateway[1199527]: ignoring rx1 downlink error: SendTimeout, module: gateway

=================================

JSON up: {"rxpk":[{"tmst":2092974491,"chan":1,"rfch":1,"freq":868.300000,"stat":1,"modu":"LORA","datr":"SF11BW12        5","codr":"4/5","lsnr":8.8,"rssi":-85,"size":17,"data":"gMoIAEgAJQIBW6pR/w5Hb5o="}]}

JSON down: {"txpk":{"imme":false,"tmst":2098974491,"freq":869.5250244140625,"rfch":0,"powe":14,"modu":"LORA","da        tr":"SF12BW125","codr":"4/5","ipol":true,"prea":null,"size":12,"data":"YMoIAEggMQEE/RdV"}}
 132508 src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=37        7746693, packet=209897

Dec 14 12:43:51 grog helium_gateway[1199527]: uplink @2092974491 us, 868.30 MHz, Ok(DataRate(SF11, BW125)), snr: 8.8, rssi: -85, len: 17 from 30:37:34:32:48:00:6C:00, module: gateway
Dec 14 12:48:07 grog helium_gateway[1199527]: rx1 downlink @2098974491 us, 869.53 MHz, DataRate(SF12, BW125), len: 12 via 30:37:34:32:48:00:6C:00, module: gateway

At some point I even wondered if there was a confusion between 5 seconds and 5 minutes in your scheduler, but I also saw smaller values

lthiery commented 1 year ago

At some point I even wondered if there was a confusion between 5 seconds and 5 minutes in your scheduler, but I also saw smaller values

tmst is given in microseconds (10^-7) so these look fine:

>>> (2429775723-2424775723)/10**6
5

However, we've noticed the error message has some bug in the logic where "too much in advance" is sometimes reported for late packets. It could simply be that these are showing up late.

What's the networking setup here? Backhaul used? Which console/LNS is the device connecting to?

Oliv4945 commented 1 year ago

Yes tmst value is correct on those last, but look at the timing from helium_gateway:

Dec 14 12:43:51 grog helium_gateway[1199527]: uplink Dec 14 12:48:07 grog helium_gateway[1199527]: rx1

This is the 5 minutes I am talking about. That said in my first post rx1_tmst=rx2_tmst, which is another issue to me

I reproduced it with an x86 computer and a rPi, both on the same corporate network. As said to @mikev privately I am waiting to go to the office next week, to try a working laptop I have at home in this network, and bring back the rPi home to see if it is related to this corporate network.

Oliv4945 commented 1 year ago

So I did further testing: the issue related to 5 minutes delay of the downlink appears only in the office, I will try to explore it with IT in order to understand why. Did you already encountered such behavior on corporate networks?

Then there is still the rx1_tmst=rx2_tmst issue which I do not find exact steps to reproduce, so as discussed with @mikev maybe the easiest way forward is the switch to Chirpstack