Inspired by your suggestion I went deeper and actually found that Kerlink Wirnet is logging the SPF output in /mnt/fsuser-1/spf/var/log/spf.log
. There I found these records:
### [JIT] ###
Dec 20 10:18:40 Wirnet local1.notice spf: /home/drd/jenkins/workspace/spf_release/lora_pkt_fwd/src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
so it definitely supports JIT queue.
Anyway I live-tried a failed join-handshake to snip its SPF log. What I got is a session where first JoinRequest fails and first retry succeeds (maybe this is what @arjanvanb asked for few posts ago?) :
Dec 20 10:45:33 Wirnet local1.notice spf: INFO: Received pkt from mote: D00XXXX0 (fcnt=46037)
Dec 20 10:45:33 Wirnet local1.notice spf: JSON up: {"rxpk":[{"tmst":2276695764,"time":"2019-12-20T10:45:33.971123Z","chan":1,"rfch":1,"freq":868.300000,"stat":1,"modu":"LORA","datr":"SF9BW125","codr":"4/5","lsnr":13.8,"rssi":-20,"size":23,"data":"AKBjAtB+1bNwa1VnUmROYUrS
Dec 20 10:45:33 Wirnet local1.notice spf: WARNING: [up] ignored out-of sync ACK packet
Dec 20 10:45:39 Wirnet local1.notice spf: INFO: [down] PULL_ACK received in 1915.86 ms
Dec 20 10:45:40 Wirnet local1.notice spf: INFO: Disabling GPS mode for concentrator's counter...
Dec 20 10:45:40 Wirnet local1.notice spf: INFO: host/sx1301 time offset=(1576836457s:275255µs) - drift=-9µs
Dec 20 10:45:40 Wirnet local1.notice spf: INFO: Enabling GPS mode for concentrator's counter.
Dec 20 10:45:40 Wirnet local1.notice spf: WARNING: [gps] GPS out of sync, keeping previous time reference
Dec 20 10:45:40 Wirnet local1.notice spf: INFO: Received pkt from mote: D00XXXX0 (fcnt=46037)
Dec 20 10:45:40 Wirnet local1.notice spf: JSON up: {"rxpk":[{"tmst":2282977668,"time":"2019-12-20T10:45:40.253025Z","chan":0,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF9BW125","codr":"4/5","lsnr":11.0,"rssi":-19,"size":23,"data":"AKBjAtB+1bNwa1VnUmROYUp3
Dec 20 10:45:40 Wirnet local1.notice spf: WARNING: [up] ignored out-of sync ACK packet
Dec 20 10:45:40 Wirnet local1.notice spf: ##### 2019-12-20 10:45:40 GMT #####
Dec 20 10:45:40 Wirnet local1.notice spf: ### [UPSTREAM] ###
Dec 20 10:45:40 Wirnet local1.notice spf: # RF packets received by concentrator: 2
Dec 20 10:45:40 Wirnet local1.notice spf: # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
Dec 20 10:45:40 Wirnet local1.notice spf: # RF packets forwarded: 2 (46 bytes)
Dec 20 10:45:40 Wirnet local1.notice spf: # PUSH_DATA datagrams sent: 3 (651 bytes)
Dec 20 10:45:40 Wirnet local1.notice spf: # PUSH_DATA acknowledged: 0.00%
Dec 20 10:45:40 Wirnet local1.notice spf: ### [DOWNSTREAM] ###
Dec 20 10:45:40 Wirnet local1.notice spf: # PULL_DATA sent: 3 (133.33% acknowledged, ping 1915.86 ms)
Dec 20 10:45:40 Wirnet local1.notice spf: # PULL_RESP(onse) datagrams received: 0 (0 bytes)
Dec 20 10:45:40 Wirnet local1.notice spf: # RF packets sent to concentrator: 0 (0 bytes)
Dec 20 10:45:40 Wirnet local1.notice spf: # TX errors: 0
Dec 20 10:45:40 Wirnet local1.notice spf: # TX rejected (collision packet): 0.00% (req:3, rej:0)
Dec 20 10:45:40 Wirnet local1.notice spf: # TX rejected (collision beacon): 0.00% (req:3, rej:0)
Dec 20 10:45:40 Wirnet local1.notice spf: # TX rejected (too late): 0.00% (req:3, rej:0)
Dec 20 10:45:40 Wirnet local1.notice spf: # TX rejected (too early): 100.00% (req:3, rej:3)
Dec 20 10:45:40 Wirnet local1.notice spf: # BEACON queued: 0
Dec 20 10:45:40 Wirnet local1.notice spf: # BEACON sent so far: 0
Dec 20 10:45:40 Wirnet local1.notice spf: # BEACON rejected: 0
Dec 20 10:45:40 Wirnet local1.notice spf: ### [JIT] ###
Dec 20 10:45:40 Wirnet local1.notice spf: /home/drd/jenkins/workspace/spf_release/lora_pkt_fwd/src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
Dec 20 10:45:40 Wirnet local1.notice spf: ### [GPS] ###
Dec 20 10:45:40 Wirnet local1.notice spf: # Valid time reference (age: 1 sec)
Dec 20 10:45:40 Wirnet local1.notice spf: # GPS coordinates: latitude 43.00000, longitude 13.00000, altitude 20 m
Dec 20 10:45:40 Wirnet local1.notice spf: ##### END #####
Dec 20 10:45:40 Wirnet local1.notice spf: JSON up: {"stat":{"time":"2019-12-20 10:45:40 GMT","lati":43.00000,"long":13.00000,"alti":20,"rxnb":2,"rxok":2,"rxfw":2,"ackr":0.0,"dwnb":0,"txnb":0,"ping":1916}}
Dec 20 10:45:40 Wirnet local1.notice spf: WARNING: [up] ignored out-of sync ACK packet
Dec 20 10:45:43 Wirnet local1.notice spf: INFO: [down] PULL_RESP received - token[102:229] :)
Dec 20 10:45:43 Wirnet local1.notice spf: JSON down: {"txpk":{"imme":false,"tmst":2281695764,"freq":868.3,"rfch":0,"powe":14,"modu":"LORA","datr":"SF9BW125","codr":"4/5","ipol":true,"size":33,"ncrc":true,"data":"IF6CIVc2FVjRUd+TSgMfGlFsLerNi8EoSbMNRwQIGy/2"}}
Dec 20 10:45:43 Wirnet local1.notice spf: /home/drd/jenkins/workspace/spf_release/lora_pkt_fwd/src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=2285897020, packet=2281695764, type=0)
Dec 20 10:45:43 Wirnet local1.notice spf: ERROR: Packet REJECTED (jit error=2)
Dec 20 10:45:44 Wirnet local1.notice spf: INFO: [down] PULL_RESP received - token[137:221] :)
Dec 20 10:45:44 Wirnet local1.notice spf: JSON down: {"txpk":{"imme":false,"tmst":2287977668,"freq":868.1,"rfch":0,"powe":14,"modu":"LORA","datr":"SF9BW125","codr":"4/5","ipol":true,"size":33,"ncrc":true,"data":"IHai0EtvQHLYVvQtjkxz57XNFHFkro3SIMcYsjbKzZbp"}}
Dec 20 10:45:50 Wirnet local1.notice spf: INFO: [down] PULL_ACK received in 765.89 ms
As you can see, comparing tmst :
- packet: 2281695764
- gw timer: 2285897020
- delta: -4201256 (TOO_EARLY)
whilst the retry:
- packet: 2287977668
- gw timer: 2286897020 (deducted)
- delta: 1080648 (OK)
Beside this, trying to write-down what one could think at this point and being open to corrections, I am understanding that GPRS gateways, although they could work well when covered with strong and jam-free signal, might not be a good idea with TTN because of bad interoperability (or at least not guaranteed) between backhaul latency and relaxed compat TTN delays. Moreover they could potentiality become sort of “bad” or “weak” nodes in the network that might lose downlink packets (that is: JoinAccept and (Un)confirmedDataDown) of nearby motes.
Does this make sense?