ERROR: Packet REJECTED, timestamp seems wrong, too much in advance about packet_forwarder HOT 12 CLOSED

@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,...

from packet_forwarder.

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?

from packet_forwarder.

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! :)

from packet_forwarder.

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

from packet_forwarder.

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.

from packet_forwarder.

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

from packet_forwarder.

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)?

from packet_forwarder.

Dear All

any solution on this ?

from packet_forwarder.

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.

from packet_forwarder.

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);

from packet_forwarder.

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.

from packet_forwarder.

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

from packet_forwarder.