search

brocaar / chirpstack-network-server

ChirpStack Network Server is an open-source LoRaWAN network-server.
https://www.chirpstack.io
MIT License
1.49k stars 546 forks source link

No ACK for valid packet #276

Closed alexanderplanar closed 6 years ago

alexanderplanar commented 6 years ago

Is this a bug or a feature request?

Bug.

What did you expect?

Receive an acknowledgement.

What happened?

The server does not send ACK packet actually, but registers the reply packet in the "frames log".

What version are your using?

loraserver version 0.22.0 lora-app-server version 0.14.1

How can your issue be reproduced?

I do not know. It is difficult to reproduce.

Could you share your log output?

Yes. See attached files. framesCSV_full_logs.zip postgre_DBs.zip server_log_full.zip ShortLogs.zip tcpdump_full_logs.zip

alexanderplanar commented 6 years ago

Hello!

Could you help me to understand the problem. I use a confirmed UpLink messages. loraserver version is 0.22.0 lora-app-server version is 0.14.1 The programs are running on Debian OS inside Virtual Box Machine. The Gateway based on BeagleBone board connected to Microchip Radio Board SX1301. The Server and the Gateway are in the same network, VM uses bridged network adapter. The hosts use NTP to time syncronisation. I noticed that sometimes some packets are not confirmed. The Node trys to retransmit the packet 8 times, but with no luck. I catched the following logs: tcpdump, syslog from network/app server and frame logs. I pass the TCPDUMP logs trough my script to filter out all LoRa packets. If it required I can upload this script, but it is just "tcpdump -i eth2 -v -XX --immediate-mode

host " 1) TCPDUMP log on gateway host: LoRaLog-GatewayMachine-UpStream LoRaLog-GatewayMachine-DownStream I pass the packets trough my script to filter out all LoRa packets. 2) TCPDUMP log on server host: LoRaLog-ServerMachine-UpStream LoRaLog-ServerMachine-DownStream I pass the packets trough my script to filter out all LoRa packets. 3) Server Logs: I just used "sudo tail -f /var/log/syslog | grep lora" to filter out all messages in SysLog corresponing to LoRaServer and ApplicationServer. 4) FrameLogs from PostgreSQL DB using pgAdmin 3 I connect to DB (loraserver_ns) and look for frame_log table: SELECT id, rx_info_set, tx_info, encode(phy_payload,'hex') FROM public.frame_log WHERE id BETWEEN 175000 AND 189000 ORDER BY created_at ASC This SQL request gives me the all packets for my case: Dec 6 2017, 9:30 AM and so on.

I found out, that the server "thinks" that it sent an ACK packet, but actually the packet is sent after about 30 second delay... (see tcpdump logs). If the issue is about MIC or radio path, the packet would be courrupted during retransmissions different way, but all 8 packets are the same. I think, the server rejects the rest packets by FCnt condition.

Could you help to solve the problem?

alexanderplanar commented 6 years ago

UPD. Do you have any special simple utility to decode payload from LoRa packet using NWKEY and APPKEY? It would help me to debug the packet exchange.

alexanderplanar commented 6 years ago

UPD. Excuse me, I found a mistake in my script, and it can affect to results. In particular, the timestamp logged in tcpdump logs is shifted relatively to packet. Now I've fixed it and going to start a new test. p.s. But it does not mean that the effect I described will disappear. It appears by itself time to time without any tests, I just try to log it and confirm it is real. As I get any results to upload, I delete old logs from issue.

Thanks!

alexanderplanar commented 6 years ago

UPD. I found out that the loraserver does not responsible for this bug, at least, It actually send response, but it may be dropped by lora-gateway. The issue can be closed. Thanks.

alexanderplanar commented 6 years ago

I reopen the issue, because it seems I found an evidence of the loraserver fault. The packet is processed too long and the reply is transmitted to late to be emitted by gateway. The gateway rejects the packet by wrong timestamp condition, because it thinks the RX1 is already closed.

The gateway error:

JSON down: {"txpk":{"imme":false,"tmst":256928027,"freq":868.3,"rfch":0,"powe":14,"modu":"LORA","datr":"SF7BW125","codr":"4/5","ipol":true,"size":12,"data":"YPwKEgegOQDEMNh9"}}
src/jitqueue.c:251:jit_enqueue(): ERROR: Packet REJECTED, timestamp seems wrong, too much in advance (current=258209393, packet=256928027, type=0)
ERROR: Packet REJECTED (jit error=2)
lgw_receive:1155: FIFO content: 1 83 2 5 1d

frame_log (SQL) log:

"id","created_at","rx_info_set","tx_info","encode"
"269677","2017-12-12 14:21:52.66489+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 8.8, ""timestamp"": 255928027, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -91, ""channel"": 1, ""size"": 29}]","null","80fc0a12078039000209e40e7e6e15d6447458d8a4c733143d0d98c4da"
"269678","2017-12-12 14:21:53.898056+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 256928027, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a03900c430d87d"
"269679","2017-12-12 14:22:31.694332+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 10}, ""loRaSNR"": 10, ""timestamp"": 294968388, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -95, ""channel"": 0, ""size"": 29}]","null","80fc0a1207803a00028069d57440a1aaceef359fb78853c76a9a9838d8"
"269680","2017-12-12 14:22:32.017671+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 10}, ""timestamp"": 295968388, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53a0003520700013a92c7b3"
"269681","2017-12-12 14:22:34.1969+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 7.5, ""timestamp"": 297653267, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -85, ""channel"": 2, ""size"": 31}]","null","80fc0a1207823b0003070283d7e610e1c0fa610104cd14e52ace8bb90787a9"
"269682","2017-12-12 14:22:34.460872+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 298653267, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53b000354070001bec23c55"
"269683","2017-12-12 14:22:36.089553+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 7.8, ""timestamp"": 299110059, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -89, ""channel"": 2, ""size"": 31}]","null","80fc0a1207823c00030702985a869e259db5d69dbb04395f7cbc685bfd22c3"
"269684","2017-12-12 14:22:36.772912+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 300110059, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53c0003560700018d687224"
"269685","2017-12-12 14:23:10.663303+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 10}, ""loRaSNR"": 13.5, ""timestamp"": 334177836, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -89, ""channel"": 0, ""size"": 29}]","null","80fc0a1207803d0002b681e8dce9b4946d22388db97e26229fadca6989"
"269686","2017-12-12 14:23:10.843752+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 10}, ""timestamp"": 335177836, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53d00035307000107ea12fe"
"269687","2017-12-12 14:23:13.207872+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 7.2, ""timestamp"": 336720739, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -87, ""channel"": 2, ""size"": 31}]","null","80fc0a1207823e000307026b014fe2b0033341169af83a352fd40c36495e32"
"269688","2017-12-12 14:23:13.395829+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 337720739, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53e000356070001f7010c21"
"269689","2017-12-12 14:23:14.783883+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 10, ""timestamp"": 338314515, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -94, ""channel"": 0, ""size"": 31}]","null","80fc0a1207823f0003070234c6a73553591ba91c824d5688abe286246d8ed2"
"269690","2017-12-12 14:23:15.003978+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 339314515, ""mac"": ""aa555a0000000101"", ""frequency"": 868100000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a53f000357070001eef37f7a"
"269691","2017-12-12 14:23:16.4028+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 7.5, ""timestamp"": 339886283, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -91, ""channel"": 2, ""size"": 31}]","null","80fc0a1207824000030702f0c5b4d28ebbbfde3dd50ac4349055e4b0965135"
"269692","2017-12-12 14:23:16.588417+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 340886283, ""mac"": ""aa555a0000000101"", ""frequency"": 868500000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a0400055cf5aec"
"269693","2017-12-12 14:23:17.878465+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 10.2, ""timestamp"": 341390931, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -93, ""channel"": 1, ""size"": 29}]","null","80fc0a1207804100022ea338463670d96ac7e330b8374137ea81e99fe0"
"269694","2017-12-12 14:23:18.102262+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 342390931, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a04100141df4e6"
"269695","2017-12-12 14:23:19.359673+05","[{""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""loRaSNR"": 8.2, ""timestamp"": 342851731, ""crcStatus"": 1, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""rfChain"": 1, ""codeRate"": ""4/5"", ""time"": ""0001-01-01T00:00:00Z"", ""rssi"": -90, ""channel"": 1, ""size"": 29}]","null","80fc0a120780420002496a9c2bdf2c61a4fe4c897cdc7ba9092d75b692"
"269696","2017-12-12 14:23:19.581786+05","null","{""iPol"": null, ""power"": 14, ""dataRate"": {""modulation"": ""LORA"", ""bandwidth"": 125, ""spreadFactor"": 7}, ""timestamp"": 343851731, ""mac"": ""aa555a0000000101"", ""frequency"": 868300000, ""codeRate"": ""4/5"", ""immediately"": false}","60fc0a1207a04200f038125f"

tcpdump (on gateway) (see pcap files attached)

+---------+---------------+----------+
**09:21:52,194,428**   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f1|6f|7d|40|00|40|11|46|84|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|dd|37|17|02|22|19|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|35|35|39|32|38|30|32|37|2c|22|63|68|61|6e|22|3a|31|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|33|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|37|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|38|2e|38|2c|22|72|73|73|69|22|3a|2d|39|31|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
**09:21:54,453,035**   ETHER
|0   |04|a3|16|ae|ef|3a|08|00|27|aa|02|f4|08|00|45|00|00|c5|45|d9|40|00|40|11|70|54|c0|a8|01|45|c0|a8|01|65|06|a4|e0|5d|00|b1|74|d3|02|00|00|03|7b|22|74|78|70|6b|22|3a|7b|22|69|6d|6d|65|22|3a|66|61|6c|73|65|2c|22|74|6d|73|74|22|3a|32|35|36|39|32|38|30|32|37|2c|22|66|72|65|71|22|3a|38|36|38|2e|33|2c|22|72|66|63|68|22|3a|30|2c|22|70|6f|77|65|22|3a|31|34|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|37|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|69|70|6f|6c|22|3a|74|72|75|65|2c|22|73|69|7a|65|22|3a|31|32|2c|22|64|61|74|61|22|3a|22|59|50|77|4b|45|67|65|67|4f|51|44|45|4d|4e|68|39|22|7d|7d|

+---------+---------------+----------+
09:21:57,200,481   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f1|70|96|40|00|40|11|45|6b|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|dd|b4|7b|02|ba|9b|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|36|30|39|32|37|37|30|37|2c|22|63|68|61|6e|22|3a|32|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|35|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|37|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|37|2e|38|2c|22|72|73|73|69|22|3a|2d|39|32|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:02,264,209   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f2|73|7e|40|00|40|11|42|82|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|de|fa|6d|02|0b|e1|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|36|35|39|38|34|35|38|38|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|38|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|32|2e|30|2c|22|72|73|73|69|22|3a|2d|39|33|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:07,510,036   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f2|77|bc|40|00|40|11|3e|44|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|de|c9|68|02|1a|1c|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|37|31|32|33|34|38|34|34|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|38|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|31|2e|32|2c|22|72|73|73|69|22|3a|2d|39|33|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:11,121,437   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f1|78|39|40|00|40|11|3d|c8|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|dd|33|1f|02|1b|13|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|37|34|38|33|38|32|35|32|2c|22|63|68|61|6e|22|3a|32|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|35|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|39|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|39|2e|38|2c|22|72|73|73|69|22|3a|2d|39|33|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:16,367,582   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f2|7b|4a|40|00|40|11|3a|b6|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|de|16|ca|02|b5|ca|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|38|30|30|38|38|35|31|36|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|39|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|33|2e|30|2c|22|72|73|73|69|22|3a|2d|39|36|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:20,307,601   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f3|7d|e2|40|00|40|11|38|1d|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|df|8d|78|02|4e|e8|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|38|34|30|32|34|33|33|32|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|31|30|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|30|2e|35|2c|22|72|73|73|69|22|3a|2d|38|39|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:24,561,858   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f3|81|a4|40|00|40|11|34|5b|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|df|97|7f|02|38|e0|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|38|38|32|37|34|37|32|34|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|31|30|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|30|2e|32|2c|22|72|73|73|69|22|3a|2d|38|39|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|51|41|43|43|65|51|4f|66|6d|34|56|31|6b|52|30|57|4e|69|6b|78|7a|4d|55|50|51|32|59|78|4e|6f|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:31,253,746   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f3|87|42|40|00|40|11|2e|bd|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|df|49|45|02|3d|34|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|39|34|39|36|38|33|38|38|2c|22|63|68|61|6e|22|3a|30|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|31|30|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|31|30|2e|30|2c|22|72|73|73|69|22|3a|2d|39|35|2c|22|73|69|7a|65|22|3a|32|39|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|41|4f|67|41|43|67|47|6e|56|64|45|43|68|71|73|37|76|4e|5a|2b|33|69|46|50|48|61|70|71|59|4f|4e|67|3d|22|7d|5d|7d|

+---------+---------------+----------+
09:22:32,108,097   ETHER
|0   |04|a3|16|ae|ef|3a|08|00|27|aa|02|f4|08|00|45|00|00|ce|52|cd|40|00|40|11|63|57|c0|a8|01|45|c0|a8|01|65|06|a4|e0|5d|00|ba|e8|3f|02|00|00|03|7b|22|74|78|70|6b|22|3a|7b|22|69|6d|6d|65|22|3a|66|61|6c|73|65|2c|22|74|6d|73|74|22|3a|32|39|35|39|36|38|33|38|38|2c|22|66|72|65|71|22|3a|38|36|38|2e|31|2c|22|72|66|63|68|22|3a|30|2c|22|70|6f|77|65|22|3a|31|34|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|31|30|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|69|70|6f|6c|22|3a|74|72|75|65|2c|22|73|69|7a|65|22|3a|31|37|2c|22|64|61|74|61|22|3a|22|59|50|77|4b|45|67|65|6c|4f|67|41|44|55|67|63|41|41|54|71|53|78|37|4d|3d|22|7d|7d|

+---------+---------------+----------+
09:22:33,939,781   ETHER
|0   |08|00|27|aa|02|f4|04|a3|16|ae|ef|3a|08|00|45|00|00|f5|88|fd|40|00|40|11|2d|00|c0|a8|01|65|c0|a8|01|45|cc|e1|06|a4|00|e1|8d|0c|02|bc|5f|00|aa|55|5a|00|00|00|01|01|7b|22|72|78|70|6b|22|3a|5b|7b|22|74|6d|73|74|22|3a|32|39|37|36|35|33|32|36|37|2c|22|63|68|61|6e|22|3a|32|2c|22|72|66|63|68|22|3a|31|2c|22|66|72|65|71|22|3a|38|36|38|2e|35|30|30|30|30|30|2c|22|73|74|61|74|22|3a|31|2c|22|6d|6f|64|75|22|3a|22|4c|4f|52|41|22|2c|22|64|61|74|72|22|3a|22|53|46|37|42|57|31|32|35|22|2c|22|63|6f|64|72|22|3a|22|34|2f|35|22|2c|22|6c|73|6e|72|22|3a|37|2e|35|2c|22|72|73|73|69|22|3a|2d|38|35|2c|22|73|69|7a|65|22|3a|33|31|2c|22|64|61|74|61|22|3a|22|67|50|77|4b|45|67|65|43|4f|77|41|44|42|77|4b|44|31|2b|59|51|34|63|44|36|59|51|45|45|7a|52|54|6c|4b|73|36|4c|75|51|65|48|71|51|3d|3d|22|7d|5d|7d|

Node log (without time, unfortunatelty)

TuneFreq: 868500 kHz
ACK received (1)
UpLink counter: 56
TuneFreq: 868500 kHz
ACK received (1)
UpLink counter: 57
TuneFreq: 868300 kHz
### Rx Packet Timeout
ReSend on ACK timeout (1 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (2 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
ReSend on ACK timeout (3 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
ReSend on ACK timeout (4 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (5 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
ReSend on ACK timeout (6 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
ReSend on ACK timeout (7 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
Give up on ACK timeout (8 >= 8)
TuneFreq: 868100 kHz
ACK received (1)
UpLink counter: 59
TuneFreq: 868500 kHz
ACK received (1)
UpLink counter: 60
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (1 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (2 < 8)
TuneFreq: 868100 kHz
### Rx Packet Timeout
ReSend on ACK timeout (3 < 8)
TuneFreq: 868300 kHz
### Rx Packet Timeout
ReSend on ACK timeout (4 < 8)
TuneFreq: 868300 kHz
### Rx Packet Timeout
ReSend on ACK timeout (5 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (6 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
ReSend on ACK timeout (7 < 8)
TuneFreq: 868500 kHz
### Rx Packet Timeout
Give up on ACK timeout (8 >= 8)
TuneFreq: 868100 kHz
ACK received (1)
UpLink counter: 62

More info is in attach files. attach.zip

Do you have any ideas, why the server process the packet so long time? I understand, that the server is running under VM, but the usual process time is about 0,3 sec, this packet was being processed during 1.3 sec.

Thanks in advance for any advice.

brocaar commented 6 years ago

Could you post your loraserver settings (no passwords secrets needed)? E.g. a long de-duplication delay could be the cause of this (as you instruct LoRa Server to wait for a long time). Also the downlink data delay adds to the time to the roundtrip. An other thing to consider, what is the roundtrip time between your gateway and the network-server? In some cases when you're using a 3G connection, it makes sense to configure the --rx1-delay to something > 1 second.

Please note, the latest release includes a downlink queue refactor! You might want to upgrade and see if the issue persists. As the queue is now stored in the LoRa Server database, LoRa Server does not need to contact LoRa App Server anymore which saves an other API request (depending your setup this might or might not be significant). See: https://forum.loraserver.io/t/release-lora-app-server-0-15-lora-server-0-23/492

alexanderplanar commented 6 years ago

Hi, @brocaar, thanks for your fast reply!

Yes, sure :)

I use local network between LoRa Server and Gateway, no VPN or 3G is used, Ethernet is used only. But the LoRa Server is running under VirtualBox with using bridged adapter. Maybe, it contributes some latency.

I do not override the default value of key --rx1-delay. it is by default - 1 second.

I updated applications recently: lora-app-server version 0.14.1 loraserver version 0.22.0

So, I will try to move my server to a host with better performance.

my /etc/default/loraserver file:

# network identifier (NetID, 3 bytes) encoded as HEX (e.g. 010203)
NET_ID=010203

# ism band configuration to use (options: AU_915_928, CN_470_510, EU_863_870, US_902_928)
BAND=EU_863_870

# ca certificate used by the api server (optional)
CA_CERT=

# tls certificate used by the api server (optional)
TLS_CERT=

# tls key used by the api server (optional)
TLS_KEY=

# ip:port to bind the api server (default: "0.0.0.0:8000")
BIND=0.0.0.0:8000

# redis url (e.g. redis://user:password@hostname:port/0) (default: "redis://localhost:6379")
REDIS_URL=redis://localhost:6379

# postgresql dsn (e.g.: postgres://user:password@hostname/database?sslmode=disable)
POSTGRES_DSN=postgres://loraserver_ns:***@localhost/loraserver_ns?sslmode=disable

# automatically apply database migrations
DB_AUTOMIGRATE=true

# mqtt broker server used by the gateway backend (e.g. scheme://host:port where scheme is tcp, ssl or ws) (default: "tcp://localhost:1883")
GW_MQTT_SERVER=tcp://localhost:1883

# mqtt username used by the gateway backend (optional)
GW_MQTT_USERNAME=sammy

# mqtt password used by the gateway backend (optional)
GW_MQTT_PASSWORD=***

# hostname:port of the application-server api server (optional) (default: "127.0.0.1:8001")
AS_SERVER=127.0.0.1:8001

# ca certificate used by the application-server client (optional)
AS_CA_CERT=

# tls certificate used by the application-server client (optional)
AS_TLS_CERT=

# tls key used by the application-server client (optional)
AS_TLS_KEY=

# hostname:port of the network-controller api server (optional)
NC_SERVER=

# ca certificate used by the network-controller client (optional)
NC_CA_CERT=

# tls certificate used by the network-controller client (optional)
NC_TLS_CERT=

# tls key used by the network-controller client (optional)
NC_TLS_KEY=

# time to wait for uplink de-duplication (default: 200ms)
DEDUPLICATION_DELAY=200ms

# delay between uplink delivery to the app server and getting the downlink data from the app server (if any) (default: 100ms)
GET_DOWNLINK_DATA_DELAY=100ms

# timezone to use when aggregating data (e.g. 'Europe/Amsterdam') (optional, by default the local timezone is used)
# TIMEZONE=Europe/Amsterdam

# create non-existing gateways on receiving of stats
GW_CREATE_ON_STATS=true

# aggregation intervals to use for aggregating the gateway stats (valid options: second, minute, hour, day, week, month, quarter, year)
GW_STATS_AGGREGATION_INTERVALS=minute,hour,day

# extra frequencies to use for ISM bands that implement the CFList
# EXTRA_FREQUENCIES=867100000,867300000,867500000,867700000

# enable only a given sub-set of channels (e.g. '0-7,64')
# ENABLE_UPLINK_CHANNELS=0-7,64

# the ttl after which a node-session expires after no activity (default 31 days)
NODE_SESSION_TTL=744h0m0s

# log uplink and downlink frames to the database
LOG_NODE_FRAMES=true

# ca certificate used by the gateway api server (optional)
GW_SERVER_CA_CERT=

# tls certificate used by the gateway api server (optional)
GW_SERVER_TLS_CERT=

# tls key used by the gateway api server (optional)
GW_SERVER_TLS_KEY=

# JWT secret used by the gateway api server for gateway authentication / authorization
# You could generate this by executing 'openssl rand -base64 32' for example
GW_SERVER_JWT_SECRET=***

# ip:port to bind the gateway api server (default: "0.0.0.0:8002")
GW_SERVER_BIND=0.0.0.0:8002
alexanderplanar commented 6 years ago

UPD. I moved the VM to the host with the higher performance, no luck. 4 lost ACKs per 5 minutes (about 200 messages).

alexanderplanar commented 6 years ago

I tried to create a full log of error, but came across to the strange problem. I noticed that the timestamps (tmst) on gateway log does not relate to the real delay of roundtrip. I suggested that the full roundtrip between the gateway and the server equals the difference btw a couple values of tmst on gateway, but it is not. The gateways reports that the packet has been rejected due to the timestamps "is too mush in advance", but the difference between timestamps is different each time: 120ms, 200ms, 1.2sec.... Why gateway rejects the packet in case the difference between timestamps is 120ms? In the same time the server reports that only the processing time is about 990 msec (frame_logs)... attach.zip

Maybe, it is seems that it is required to adjust the RXDELAY1 and RXDELAY2 to get the network works stable...

I will try to update the apps to the new version (15) tomorrow

brocaar commented 6 years ago

When you also upgrade to LoRa Gateway Bridge 2.2.0 you'll be able to see the packet-forwarder ACKs and nACKS, which could be helpful too for debugging :-) See gateway/[mac]/ack.

alexanderplanar commented 6 years ago

Hello, @brocaar ! Thanks for advice :-) Could you explain, if the LoRa Gateway Bridge is the proxy-like application, which will be retranslate the packets between the LoRa Network Server and LoRa Gateway? Now on my Beaglebone the only application is running: LoRa Gateway Packet Forwarder. It connects to the LoRa Network Server directly using UDP Semtech. Do I understand correctly, LoRa Gateway Bridge will wedge into the exchange between the gateway and server?

alexanderplanar commented 6 years ago

@brocaar, I've updgraded the apps, but with no results. The problem is still actual. Current used versions: loraserver version 0.23.0 lora-app-server version 0.15.0

By the way, I want to note, I changed the application duty cycle, so my Node sends about one packet per second, of course in case the ACK is received by the Node. It causes the problem to show up fast. Today I get the error approximately each 1 minute (1/40 packets).

So, I also will try to configure LoRa Gateway Bridge to get more information.

alexanderplanar commented 6 years ago

Hello, @brocaar I did some tests with LoRa Gateway Bridge on the gateway host, but with no luck. The problem is still actual. In particular, I see ACK, TX and RX events when I type 'mosquitto_sub -v -t "gateway/+/#", but I do not see nACKS. In the same time the nACKS actually are, because I see JIT-errors in the packet forwarder logs, and I see the packet retransmissions.

UPD. I made SPI-stress test on the gateway host and I fixed the problem with the connectivity via SPI cable. After 14-hour test there no errors more. But the problem with the packet retransmissions is still actual.

brocaar commented 6 years ago

But the problem with the packet retransmissions is still actual.

Just to make sure I don't make any assumptions, you mean that LoRa Server does not ACK a confirmed data re-transmission? (https://github.com/brocaar/loraserver/issues/272)

alexanderplanar commented 6 years ago

Hello, @brocaar! No, I mean, the server does respond to confirmed uplink, but too late to the ACK packet can be transmitted by the gateway. So, the gateway rejects the packet by the timestamp condition (JIT error = 2, timestamp seems wrong). Therefore the server "thinks" that the packet already confirmed (the ACK has been emitted by server), but actually the gateway rejected the packet. And the node unable to determine if the packet lost on uplink path, or downlink path, and begins the long procedure of retransmission. But each retransmission must be ignored by server, because server "thinks" the packet already confirmed and does not respond.

alexanderplanar commented 6 years ago

have to note, this situation happens time to time, and the system works in general. But sometimes something goes wrong and the server process the packet longer than usually.

brocaar commented 6 years ago

Yes, I'm aware of that and I will improve this. For the time being, you could increase the --rx1-delay setting so you have more time for the roundtrip. When you know that you never have to wait for the application-server to enqueue data, directly after an uplink, you could also set --get-downlink-data-delay to 0.

I'm also planning to add more debug logging with timing, so it is easier to debug which function consumes what amount of time.

For the gateway communication, the first effort was to expose the gateway/MAC/ack topic, so this feedback can be used by LoRa Server in the future :-)

alexanderplanar commented 6 years ago

Ok, thanks for advice, I will try to change RXDELAY1. But if I change rxdelay1, would I need to change rxdelay2? As I understand correct, the RXDELAY1 and RXDELAY2 is related to the same moment of time: the time of transmitting, RXDELAY2 = RXDELAY1 + 1, isn't it?

brocaar commented 6 years ago

That is correct and you only have to set the rx1 delay, as the rx2 delay is always rx1 delay + 1 second.

alexanderplanar commented 6 years ago

Perfect, thanks! ;-)

alexanderplanar commented 6 years ago

Happy New Year everyone!

@brocaar, Hello! I made a test at holydays. I changed the RXDELAY1 to 2 seconds. I made some changes in the firmware of the node to make it to send all statistics to the server. Then I parse this data using mosquitto_sub and some script magic :) Finally I process the data packet by my mini-tool in C. Here is the result: Duration: 11 days (949064 seconds) Packets sent: 300655 Packets without ACK: 953 (0.3170%) RX Timeouts: 7942 Packets received: 300654 RX Errors: 692

I think is not bad :) but is not ideally. I double checked the last lost packet and got see that the packet processed fast enough (about 200ms - from 'frame_logs' table in DB). Then I checked the packet forwarder log, and did not found any records telling the packet had been rejected. I thought the issue is the ACK-packets are rejected by packet_forwarder by JIT error and so it is not emitted. But now I use a new version of network server (0.23), and I do not see such errors . So the ACK has been sent apparently. But the node does not receive it due to some reason. Maybe it is the firmware issue, maybe, it depends on some kind of ether noise, I do not know for sure. More over I see lots of errorneous RX-packets. You said a couple weeks ago that you going to improve something in network server relating to the packet processing. Maybe it is better to do a new long test after this fix to be sure that the problem does not refers to network server at all. Could you tell when the new version will be released approximately?

Thanks a lot!

brocaar commented 6 years ago

You said a couple weeks ago that you going to improve something in network server relating to the packet processing. Maybe it is better to do a new long test after this fix to be sure that the problem does not refers to network server at all. Could you tell when the new version will be released approximately?

Yes, I want to handle downlink messages in a smarter way, but this should only affect downlink transmissions that initially failed because of a nACK by LoRa Gateway Bridge / the packet-forwarder. E.g. in case one gateway is unable to transmit, re-try using RX2 parameters (if possible) or a different gateway on RX1 or RX2. I don't have an ETA for this yet.

brocaar commented 6 years ago

Is this issue still present? Else I will close this issue.