rxpk[0].time not chronological

[Kamilcuk]

I have iC880A connected to my device. I am running packet-forwarder on it. I have an external GPS connected via usb to my device and I have added "gps_tty_path" to local_conf.json. Packet-forwarder correctly connects to GPS device. However the GPS PPS signal is not conected to iC880A. Machine time is synchronized with GPS time, GPS has fix. My timezone is UTC+1. The problem i have, is that packets received by packet-forwarder have wrong rxpk[0].time value, usually many seconds in the future and those values are not in chronological order. Here are example of my logs:

Jan 26 19:34:28 JSON up: {"rxpk":[{"tmst":2775041860,"time":"2017-01-26T18:35:25.023600Z","chan":0,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF9BW125","codr":"4/5","lsnr":-0.8,"rssi":-115,"size":14,"data":"XXXXXX="}]}
Jan 26 19:34:28 INFO: [up] PUSH_ACK received in 102 ms
Jan 26 19:34:30 INFO: [down] PULL_ACK received in 110 ms
Jan 26 19:34:31 
Jan 26 19:34:31 ##### 2017-01-26 18:34:31 GMT #####
Jan 26 19:34:31 ### [UPSTREAM] ###
Jan 26 19:34:31 # RF packets received by concentrator: 6
Jan 26 19:34:31 # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
Jan 26 19:34:31 # RF packets forwarded: 6 (106 bytes)
Jan 26 19:34:31 # PUSH_DATA datagrams sent: 7 (1580 bytes)
Jan 26 19:34:31 # PUSH_DATA acknowledged: 85.71%
Jan 26 19:34:31 ### [DOWNSTREAM] ###
Jan 26 19:34:31 # PULL_DATA sent: 3 (100.00% acknowledged)
Jan 26 19:34:31 # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Jan 26 19:34:31 # RF packets sent to concentrator: 0 (0 bytes)
Jan 26 19:34:31 # TX errors: 0
Jan 26 19:34:31 # BEACON queued: 0
Jan 26 19:34:31 # BEACON sent so far: 0
Jan 26 19:34:31 # BEACON rejected: 0
Jan 26 19:34:31 ### [JIT] ###
Jan 26 19:34:31 src/jitqueue.c:511:jit_print_queue(): INFO: [jit] queue is empty
Jan 26 19:34:31 ### [GPS] ###
Jan 26 19:34:31 # Valid time reference (age: 0 sec)
Jan 26 19:34:31 # GPS coordinates: latitude XXXXXX, longitude XXXXXX, altitude 95 m
Jan 26 19:34:31 ##### END #####
Jan 26 19:34:31 
Jan 26 19:34:31 JSON up: {"stat":{"time":"2017-01-26 18:34:31 GMT","lati":XXXXXX,"long":XXXXXX,"alti":95,"rxnb":6,"rxok":6,"rxfw":6,"ackr":85.7,"dwnb":0,"txnb":0}}
Jan 26 19:34:31 
Jan 26 19:34:31 INFO: Disabling GPS mode for concentrator's counter...
Jan 26 19:34:31 INFO: host/sx1301 time offset=(1485452893s:325012<C2><B5>s) - drift=60<C2><B5>s
Jan 26 19:34:31 INFO: Enabling GPS mode for concentrator's counter.
Jan 26 19:34:31 
Jan 26 19:34:31 INFO: [up] PUSH_ACK received in 63 ms
Jan 26 19:34:31 
Jan 26 19:34:31 INFO: Received pkt from mote: XXXXXX (fcnt=643)
Jan 26 19:34:31 
Jan 26 19:34:31 JSON up: {"rxpk":[{"tmst":2778433348,"time":"2017-01-26T18:35:31.415089Z","chan":2,"rfch":1,"freq":868.500000,"stat":1,"modu":"LORA","datr":"SF9BW125","codr":"4/5","lsnr":3.8,"rssi":-115,"size":19,"data":"XXXXXX=="}]}
Jan 26 19:34:31 INFO: [up] PUSH_ACK received in 79 ms
Jan 26 19:34:33 
Jan 26 19:34:33 INFO: Received pkt from mote: XXXXXX  (fcnt=418)
Jan 26 19:34:33 
Jan 26 19:34:33 JSON up: {"rxpk":[{"tmst":2780060292,"time":"2017-01-26T18:34:35.041228Z","chan":4,"rfch":0,"freq":867.300000,"stat":1,"modu":"LORA","datr":"SF9BW125","codr":"4/5","lsnr":1.0,"rssi":-119,"size":19,"data":"XXXXXX=="}]}

Packet received on 19:34:28 has "time":"2017-01-26T18:35:25.023600Z", that is 57 seconds in the future. Packet received on 19:34:33 has "time":"2017-01-26T18:34:35.041228Z", that is only 2 seconds in the future, and the value is before "2017-01-26T18:35:25.023600Z". The second packet was received (and sended) AFTER the first one, but the "time" field in jsons are not chronological (and are in the future). I discovered that this "time difference" lowers whenever the loop in thread_timersync() runs. Will connecting PPS signal to iC880A fix the issue?

[abouillot]

Not sure to have a correct answer, but is your system clock correct with regards to GPS time? According to your log, I understand you have a GPS attached to the system. This provide time to the packet received. However, as you've noticed, the log's time stamps are not aligned. I would suspect a clock synchronisation issue.

[Kamilcuk]

Yes, i have checked it multiple times, to be sure that it isn't my machine fault. ntpd synchronizes time with both external ntp servers and gps time. ntpq -p reports offset of ~20 miliseconds. To receive gps nmea messages by both packet-forwarder and gpsd, i have duplicated gps nmea stream using socat ('/usr/bin/gpspipe -r | /usr/bin/socat - PTY,link=/dev/%i,raw'). This could alter time, but packet-forwarder uses read(..) to read from socket, and this shouldn't change rxpk[0].time every 60 seconds in repeatable way. For every "rxpk" line in my logs I have calculated the difference between system time and the time reported in rxpk[0].time. The difference raises up to about 60 seconds, then the thread_timersync() runs ( there is wait_ms(60000) in thread_timersync() ), and then the difference goes back to about 0. This repeats every 60 seconds. It seems for me, like the difference is rising "one second per second" after every thread_timesync() run. I can try to post more logs, probably on hastebin, if You wish. My idea: if there's no PPS signal connected to iC880A, when lgw_reg_w(LGW_GPS_EN, x) is toggled, than the internal iC880A clock is changing, and somehow this value is added to the rxpk.time (?)...

[mcoracin]

For the conversion from sx1301timestamp to UTC time to work, the PPS signal has to be connected to the SX1301.