search

Lora-net / packet_forwarder

A LoRa packet forwarder is a program running on the host of a LoRa gateway that forwards RF packets receive by the concentrator to a server through a IP/UDP link, and emits RF packets that are sent by the server. This project is associated to the lora_gateway repository for SX1301 chip. For SX1302/1303, the repository sx1302_hal must be used.
Other
726 stars 668 forks source link

ERROR: Packet REJECTED, timestamp seems wrong, too much in advance #31

Closed brixworth closed 7 years ago

brixworth commented 7 years ago

Randomly getting the above error when sending packets back from a network server to the gateway. The error is misleading because the txpk packet was received by the gateway in time and queued on the JIT queue but come the time to process it, the current time is AFTER the timestamp in the packet as can be seen in this log message:

`JSON down: {"txpk":{"imme":false,"tmst":1171949259,"freq":868.5,"rfch":0,"powe":14,"modu":"LORA","datr":"SF7BW125","codr":"4/5","ipol":true,"size":17,"data":"IAEaZceWDv2zLGE/G78VyXQ="}}

src/jitqueue.c:314:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=1171981382, packet=1171949259, type=0) ERROR: Packet REJECTED (jit error=2)`

The potential for a problem seems to have already been considered as there is a comment immediately above the line causing the issue:

* Warning: unsigned arithmetic (handle roll-over) t_packet > t_current + TX_MAX_ADVANCE_DELAY

The problem lines are lines 232 and 250 of jitqueue.c

TIA

mcoracin commented 7 years ago

As the rejection happens before inserting the packet in the JiT queue, it could be explained by a network latency, implying the packet to reach the gateway a bit too late compared to its departure time.

I don't think this issue is related to any roll-over problem. It just seems that the packets arrives 32ms too late within the 1 seconds allowed by the RX window 1.

When you say that the packet arrives in time in the gateway, where did you measure it? For sure there is some latency introduced by the packet forwarder and JiT queue, so it the packet arrives on the UDP socket just before its departure time, it is too late.

Which host CPU are you using?

brixworth commented 7 years ago

My bad Michael, it was some delay in the message being received by the packet forwarder. Apologies for raising this but thanks for taking the trouble to respond! :)

vikasrohal commented 7 years ago

Hi I am also facing this type of issue

JSON up: {"rxpk":[{"tmst":222201908,"chan":3,"rfch":0,"freq":865.742500,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":7.5,"rssi":-79,"size":64,"data":"gAQAAACABgADYSsBp5JnfPtTrPwi0NVJZb+z+YdzfTeNsTtOZaq/eZGRXG8SukR1hXWw+xXJJpcpgm4puYMbpA=="}]} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [up] PUSH_ACK received in 5 ms Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [down] PULL_RESP received - token[0:0] :) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: JSON down: {"txpk":{"imme":false,"tmst":223201908,"freq":865.7425,"rfch":0,"powe":27,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"size":12,"data":"YAQAAACgNgNkIjbl"}} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=223434491, packet=223201908, type=0) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: ERROR: Packet REJECTED (jit error=2) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: Received pkt from mote: 11111111 (fcnt=28) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: JSON up: {"rxpk":[{"tmst":223103340,"chan":6,"rfch":1,"freq":866.495000,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":1.5,"rssi":-84,"size":50,"data":"gBEREREBHAACAwICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAr+OTbw="}]} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [up] PUSH_ACK received in 8 ms Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [down] PULL_RESP received - token[0:0] :) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: JSON down: {"txpk":{"imme":false,"tmst":224103340,"freq":866.495,"rfch":0,"powe":27,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"size":15,"data":"YBERERGjBAACFQFRITKs"}} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=224336254, packet=224103340, type=0) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: ERROR: Packet REJECTED (jit error=2) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: Received pkt from mote: 00000004 (fcnt=6) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: JSON up: {"rxpk":[{"tmst":230202876,"chan":3,"rfch":0,"freq":865.742500,"stat":1,"modu":"LORA","datr":"SF12BW125","codr":"4/5","lsnr":2.5,"rssi":-79,"size":64,"data":"gAQAAACABgADYSsBp5JnfPtTrPwi0NVJZb+z+YdzfTeNsTtOZaq/eZGRXG8SukR1hXWw+xXJJpcpgm4puYMbpA=="}]} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [up] PUSH_ACK received in 22 ms Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [down] PULL_ACK received in 24 ms Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: INFO: [down] PULL_RESP received - token[0:0] :) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: JSON down: {"txpk":{"imme":false,"tmst":231202876,"freq":865.7425,"rfch":0,"powe":27,"modu":"LORA","datr":"SF12BW125","codr":"4/5","ipol":true,"size":12,"data":"YAQAAACgNwNk6T/3"}} Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=231446379, packet=231202876, type=0) Aug 23 14:30:07 raspberrypi iC880-SPI_reset_backup.sh[404]: ERROR: Packet REJECTED (jit error=2)

I am using latest Lora gateway version and packet forwarder

nanomo commented 6 years ago

Im having this issue too, in my case the difference on the timestamp are higher

ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=1543746330, packet=1422659915, type=0)

I checked the OS timezone for loraserver and the gateway, are the same, i cant figure out why the big difference.

ghost commented 6 years ago

Even i am getting this same error.please help me to resolve this

KillingJacky commented 5 years ago

I also think it's different between: (t_packet - t_current) > TX_MAX_ADVANCE_DELAY and t_packet > (t_current + TX_MAX_ADVANCE_DELAY),

The former one may introduce roll-over problem, why not use the later one (also the comment suggest so)?

takis264 commented 4 years ago

Dear All

any solution on this ?

CyrilBrulebois commented 3 years ago

Hey folks,

What about the following patch? 0001-Get-current-UNIX-time-after-getting-concentrator-s-t.patch.txt

I'm seeing this issue with a different component (picoGW_packet_forwarder) but this issue turned up when looking for the error string, and it seems src/timersync.c is shared across several projects, so I'm proposing a patch similar to the one I've suggested for icoGW_packet_forwarder.

queifaro commented 3 years ago

Hello, what do you think about / TODO: handle sx1301 coutner wrap-up / in timersync thread as in few others place of the packet forwarder code ?

/ Compute offset between unix and concentrator timers, with microsecond precision / offset_previous.tv_sec = offset_unix_concent.tv_sec; offset_previous.tv_usec = offset_unix_concent.tv_usec;

    /* TODO: handle sx1301 coutner wrap-up */
    pthread_mutex_lock(&mx_timersync); /* protect global variable access */
    timersub(&unix_timeval, &concentrator_timeval, &offset_unix_concent);
    pthread_mutex_unlock(&mx_timersync);
CyrilBrulebois commented 3 years ago

I don't remember the exact specifics, but I seem to recall that some 32-bit related overflow/wrap-up happens with my customer's code. I think it's self-correcting (just generates a log line), but I don't remember whether that's managed by the packet forwarder code or by my customer's code.

ofauchon commented 3 years ago

Hi all,

I can reproduce the bug with my Dragino gateway: Device Model: | LPS8 Hostname: | dragino-1ebbcc Firmware: | lgw-5.4.1607519907 Build Time: | Build Wed Dec 9 21:18:27 CST 2020

Mon Feb 1 16:50:29 2021 daemon.info lora_pkt_fwd[15730]: PKT_FWD~ JOIN_REQ+ {"AppEUI":, "02010000000000A0", "DevEUI":, "01A00A000000ADDE"} Mon Feb 1 16:50:30 2021 daemon.info lora_pkt_fwd[15730]: RXTX~ {"rxpk":[{"tmst":104356491,"time":"2021-02-01T16:50:30.105840Z","chan":1,"rfch":1,"freq":868.300000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":9.8,"rssi":-51,"size":23,"data":"AAIBAAAAAACgAaAKAAAArd4AuMBcGwI="}]} Mon Feb 1 16:50:37 2021 daemon.info lora_pkt_fwd[15730]: RXTX~ {"txpk":{"imme":false,"tmst":109356491,"freq":868.3,"rfch":0,"powe":14,"modu":"LORA","datr":"SF7BW125","codr":"4/5","ipol":true,"size":33,"ncrc":true,"data":"IIPInNBjHfRJxCxxXBmeFbPhT+oQNDj2jgkJnS8X4JEW"}} Mon Feb 1 16:50:37 2021 daemon.info lora_pkt_fwd[15730]: ERROR~ Packet REJECTED (jit error=2) Mon Feb 1 16:50:37 2021 daemon.info lora_pkt_fwd[15730]: PKT_FWD~ JOIN_ACCEPT+ {"NetID": "D0631D", "DevAddr": "2CC449F4"}

Any news about the fix ?

Thanks

Olivier

reissjason commented 3 years ago

@ofauchon

Looking at the log timestamps and "tmst" offset it appears that this packet did not make it to the gateway in time to be transmitted. The diff between tmst values is 5 seconds and the log shows 7 seconds difference between rx and tx messages.

Mon Feb 1 16:50:30 2021 daemon.info lora_pkt_fwd[15730]: RXTX~ {"rxpk":[{"tmst":104356491,... Mon Feb 1 16:50:37 2021 daemon.info lora_pkt_fwd[15730]: RXTX~ {"txpk":{"imme":false,"tmst":109356491,...