Interpreting debug output from Pygate

[d.alvrzx]

Re: How to interpret the output from the pygate and how to debug communication problems?

Hello everyone,

Following up on what @jand asked in the thread above, regarding the interpretation of the debug messages. Would anyone be able to point me to a place where these messages are further explained? (As to what they mean and if I should worry about any one message in particular).

For example, I have a Pygate + LoPy4 working correctly with a WiFi backhaul, following the standard tutorial on the Pycom docs. I have been receiving uplinks from a node sucessfully for about 3 hours now, but occasionally when an uplink is detected I get these messages:

[318203710] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 0
[318203760] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 1
[318205666] lorapf: INFO_ [up  ] received pkt from mote: 95ED56B1 (fcnt=34848/8820), RSSI -49.0
[318205668] lorapf: WARN_ [up  ] ignored out-of sync PUSH_ACK packet buff_ack[2:61] != token[2:62]
[318205721] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 1
[318233617] lorapf: INFO_ [main] report

From what I've been able to grasp, the INFO_ [up ] received pkt from mote: 95ED56B1 (fcnt=34848/8820), RSSI -49.0 marks the correct reception of the uplink packet, but what do the timeouts mean? What about the WARN_ [up ] ignored out-of sync PUSH_ACK packet buff_ack[2:61] != token[2:62]?

Any help with this (maybe @Gijs ) would be greatly appreciated.

Best,

Dan

[Gijs]

Hi,
In the following days I will work on a guide explaining these messages.
You are correct about this line. It represent a correctly received LoRa packet with RSSI -49 dBm

INFO_ [up ] received pkt from mote: 95ED56B1 (fcnt=34848/8820), RSSI -49.0

What happens here is that the push acknowledgement from TTN of the packet is not received (it will check twice with 5ms wait in between) here:

[318203710] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 0
[318203760] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 1

Then later the acknowledgement is received, while the gateway is expecting the push acknowledgement from the next packet. In the second try, no ack is received.

[318205668] lorapf: WARN_ [up  ] ignored out-of sync PUSH_ACK packet buff_ack[2:61] != token[2:62]
[318205721] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 1

There is nothing to worry about here generally. Sometimes the TTN acknowledgements arrive out of sync. We will have the source of the Pygate out there soon, where more information is given!

Best,
Gijs

[d.alvrzx]

Thank you, @Gijs, very kind of you to reply. I will be expecting that guide!

[d.alvrzx]

@Gijs Hello again, one other question regarding the interpretation of the debug messages:

I am now testing the downlinks from my Chirpstack server to a LoPy4 node via the Pygate. Downlinks seem to be coming in through just fine, but I am getting these IGNORED: not REJECTED, already too late to send it messages:

[591156645] lorapf: WARN_ [up  ] ignored out-of sync PUSH_ACK packet buff_ack[0:27] != token[0:28]
[591156695] lorapf: WARN_ [up  ] PUSH_ACK recieve timeout 1
[591168333] lorapf: INFO_ [down] a packet will be sent in "immediate" mode
[591168334] lorapf: INFO_ jitqueue: Current concentrator tv_sec=3958 time_us=3958638824, pkt_type=2, packet->count_us=0, (c-t)=336328472/336328472 us = 336/336 s
[591168343] lorapf: WARN_ jitqueue: IGNORED: not REJECTED, already too late to send it (current=3958638824, packet=3959638824, type=2)
[591186631] lorapf: INFO_ [main] report
##### 2020-08-25 01:30:20 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 2
# CRC_OK: 0.00%, CRC_FAIL: 100.00%, NO_CRC: 0.00%
# RF packets forwarded: 0 (0 bytes)
# PUSH_DATA datagrams sent: 1 (111 bytes)
# PUSH_DATA acknowledged: 0.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (66.67% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (176 bytes)
# RF packets sent to concentrator: 1 (18 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:3, rej:0)
# TX rejected (collision beacon): 0.00% (req:3, rej:0)
# TX rejected (too late): 0.00% (req:3, rej:0)
# TX rejected (too early): 0.00% (req:3, rej:0)
### [JIT] ###
[jit] queue is empty
### [GPS] ###
# GPS sync is disabled
##### END #####

What do these mean? Something I should worry about?

Thx,

Dan

[Gijs]

The line

IGNORED: not REJECTED, already too late to send it

Happens when a downlink packet is received from TTN later than expected, but it is still send out. The issue is that the RX window of the LoRa node might have closed already, causing the packet to never be received. As you see in the status logs, there are 0 TX errors and 1 LoRa packet sent to concentrator in the downstream section.

If this always happens with you, check the network interface latency to your TTN server, it might be quite high. We have seen this issue before with using the incorrect frequency plans (check the config.json, TTN and node frequency / region settings). Not all TTN server support all frequency plans

Best,
Gijs

[d.alvrzx]

@Gijs my nodes are all running as Class C LoRa devices, so the RX window is always open. In this sense, this warning shouldn't be an issue?

[Gijs]

In that case, the downlink messages should be received by the nodes right? There should not be any issue. Generally, LoRa nodes run class A by default to save power, therefor having a short RX window.

[d.alvrzx]

@Gijs Yes, the downlink messages are received by the nodes regardless of the time of transmission. I suppose it's normal to have that warning pop up, because in my case the downlinks are initiated by the user (me) at an arbitrary time, so it would be a big coincidence for that to match with the standard RX window of a class A device.