How Downlinks are triggered?

webfrank commented 7 years ago

Hi, I've setup a second node with address 0x000002 (the previous one is 0x000001). Now for every uplink received the server sends a scheduled packet for 0x000001 which is off:

rxpk 014846005ccf7ff42f2cd6be message {"rxpk":[{"rssi":-42,"stat":1,"modu":"LORA","rfch":1,"tmst":376197506,"datr":"SF7BW125","lsnr":8,"time":"2017-06-05T06:56:23.362268Z","codr":"4/5","data":"QAIAAAAACwABhdMoRDIE","freq":868.100,"chan":0,"size":15}]} length 225 txpk {"txpk":{"powe":14,"imme":false,"tmst":378197506,"codr":"4/5","datr":"SF12BW125","freq":869.525,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAACBBwAG8w5dQg=="}} txpk_ack {"txpk_ack":{"error":"NONE"}} transmitPkt 16325 11562 -2 869525000 192 112 2 64 14 13

schermata 2017-06-05 alle 09 01 14

gotthardp commented 7 years ago

Do you send some data over MQTT or does the server sends the downlink without your intervention?

webfrank commented 7 years ago

I send some data to devaddr 000001 via mqtt which is now off but once connected 000002 the gateway tries to send the last packet to 000001.

I noticed that the server tries to transmit forever the last packet.

In data 5 giugno 2017 9:35:07 AM Petr Gotthard notifications@github.com ha scritto:

Do you send some data over MQTT or does the server sends the downlink without your intervention?

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/gotthardp/lorawan-server/issues/118#issuecomment-306123317

gotthardp commented 7 years ago

This is definitely wrong. Will you please investigate this in more details?

Was the MQTT message sent as confirmed?
What is in the Scheduled Downlinks lists for each of the nodes? Is the packet listed there or not?
Could you provide me with the debug.log (last 50 lines), please?

webfrank commented 7 years ago

Hi, I sent not confirmed message ({"devaddr": "00000002","data": "T0s="}}, from documentation confirmed is false by default) and I could see it in scheduled downlinks till a packet is received and after gateway issues PULL_RESP is deleted and I can see it on gateway log (the previuos one) but the same packet is transmitted for every received uplink.

The two nodes actually shares the same Network Key and Application Key, only different DevAddr.

schermata 2017-06-05 alle 15 07 42

Gateway Log

rxpk  0141eb005ccf7ff42f2cd6be        message {"rxpk":[{"rssi":-43,"stat":1,"modu":"LORA","rfch":1,"tmst":27318703,"datr":"SF7BW125","lsnr":9,"time":"2017-06-05T13:08:54.203349Z","codr":"4/5","data":"QAIAAAAAGgABIoLCPaHJ","freq":868.100,"chan":0,"size":15}]}        length  224
txpk    {"txpk":{"powe":14,"imme":false,"tmst":28318703,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":27,"data":"YAIAAAABKgIGAR9BMp6bZZ5ih5NwQgLYtMc6"}}
txpk_ack        {"txpk_ack":{"error":"NONE"}}
transmitPkt     16323   11096   0       868100000       112     112     2       64      14      27
rxpk    011d9e005ccf7ff42f2cd6be        message {"rxpk":[{"rssi":-43,"stat":1,"modu":"LORA","rfch":1,"tmst":60330458,"datr":"SF7BW125","lsnr":8,"time":"2017-06-05T13:09:27.215113Z","codr":"4/5","data":"QAIAAAAAGwABH7R4CA4F","freq":868.100,"chan":0,"size":15}]}        length  224
txpk    {"txpk":{"powe":14,"imme":false,"tmst":61330458,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABKwIGdtGVWg=="}}
txpk_ack        {"txpk_ack":{"error":"NONE"}}
transmitPkt     15778   10562   -2      868100000       112     112     2       64      14      13
rxpk    0133fa005ccf7ff42f2cd6be        message {"rxpk":[{"rssi":-43,"stat":1,"modu":"LORA","rfch":1,"tmst":93632675,"datr":"SF7BW125","lsnr":8,"time":"2017-06-05T13:10:00.517320Z","codr":"4/5","data":"QAIAAAAAHAABxqyt8Tg1","freq":868.100,"chan":0,"size":15}]}        length  224
txpk    {"txpk":{"powe":14,"imme":false,"tmst":94632675,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABLAIGnMrK1g=="}}
txpk_ack        {"txpk_ack":{"error":"NONE"}}
transmitPkt     16703   11474   -2      868100000       112     112     2       64      14      13
rxpk    0163fc005ccf7ff42f2cd6be        message {"rxpk":[{"rssi":-42,"stat":1,"modu":"LORA","rfch":1,"tmst":126604584,"datr":"SF7BW125","lsnr":8,"time":"2017-06-05T13:10:33.489229Z","codr":"4/5","data":"QAIAAAAAHQABj9ZVRnpc","freq":868.100,"chan":0,"size":15}]}       length  225
txpk    {"txpk":{"powe":14,"imme":false,"tmst":127604584,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABLQIGdaaXTQ=="}}
txpk_ack        {"txpk_ack":{"error":"NONE"}}
transmitPkt     16158   11161   -3      868100000       112     112     2       64      14      13

debug.log

2017-06-05 13:05:29.636 [info] <0.250.0> server started
2017-06-05 13:05:29.674 [debug] <0.250.0> Supervisor lorawan_sup started lorawan_gw_router:start_link() at pid <0.252.0>
2017-06-05 13:05:29.681 [debug] <0.250.0> Supervisor lorawan_sup started lorawan_gw_forwarder:start_link([{port,1680}]) at pid <0.253.0>
2017-06-05 13:05:29.684 [debug] <0.250.0> Supervisor lorawan_sup started lorawan_connector_sup:start_link() at pid <0.254.0>
2017-06-05 13:05:29.704 [debug] <0.256.0>@lorawan_connector_mqtt:init:23 Connecting MQTT to mqtt://ovh1.bizmate.it:1883
2017-06-05 13:05:29.749 [debug] <0.254.0> Supervisor lorawan_connector_sup started lorawan_connector_mqtt:start_link({mqtt,[],"ovh1.bizmate.it",1883,"/",[]}, {connector,<<"MQTT">>,true,<<"mqtt://ovh1.bizmate.it:1883">>,<<"lora/{devaddr}/tx">>,<<"lora/+/rx">>,...}) at pid <0.256.0>
2017-06-05 13:05:29.749 [debug] <0.250.0> Supervisor lorawan_sup started lorawan_connector_factory:start_link() at pid <0.255.0>
2017-06-05 13:05:29.749 [info] <0.33.0> Application lorawan_server started on node lorawan@lorawan
2017-06-05 13:05:29.752 [debug] <0.258.0> Supervisor inet_gethost_native_sup started undefined at pid <0.259.0>
2017-06-05 13:05:29.752 [debug] <0.59.0> Supervisor kernel_safe_sup started inet_gethost_native:start_link() at pid <0.258.0>
2017-06-05 13:08:32.234 [info] <0.252.0> gateway 5CCF7FF42F2CD6BE {connected,{{172,17,0,1},39424}}
2017-06-05 13:08:52.554 [debug] <0.477.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:08:57.220 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}
2017-06-05 13:09:25.554 [debug] <0.509.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:09:27.223 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}
2017-06-05 13:09:58.917 [debug] <0.521.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:10:27.229 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}
2017-06-05 13:10:31.887 [debug] <0.525.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:10:57.234 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}
2017-06-05 13:11:05.376 [debug] <0.530.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:11:27.146 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}
2017-06-05 13:11:38.553 [debug] <0.549.0>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]
2017-06-05 13:11:57.152 [warning] <0.252.0> gateway 5CCF7FF42F2CD6BE {downlinks_lost,1}

On the radio side, using an SDR, I could confirm the node transmission and immediately after the gateway transmission on same channel/SF.

gotthardp commented 7 years ago

The txpk and rxpk messages are both from/for "00000002". This is correct. You wrote that the frame is in the Downlinks list until an uplink comes and then it gets transmitted and deleted from the list. This is also correct.

What is wrong then?

webfrank commented 7 years ago

Hi, in this last try I sent only one packet to node 000002 but the server/gateway tries to send it forever. If I start from scratch sending to node 000001 but connecting 000002 I still receive forever the packet sent for 000001

gotthardp commented 7 years ago

few more questions, please:

what MQTT topic do you use?
does the message disappear from the Downlinks list and gets constantly transmitted, or it keeps listed there?
is the message listed under Downlinks for 000001 or 000002?

webfrank commented 7 years ago

Hi, I send the message to {devaddr}.

The message disappears after first transmission and is listed under the correct node.

Finaly I got a kerlink gateway and I will try with it.

In data 7 giugno 2017 7:00:58 PM Petr Gotthard notifications@github.com ha scritto:

few more questions, please:

what MQTT topic do you use?

does the message disappear from the Downlinks list and gets constantly transmitted, or it keeps listed there?

is the message listed under Downlinks for 000001 or 000002?

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/gotthardp/lorawan-server/issues/118#issuecomment-306858980

gotthardp commented 7 years ago

Thanks! I am becoming desperate. You did everything right, the server appears correct, no log is written and still it doesn't work.

Which server version are you using? Would you be able to build the latest master and try that, please? It may write some more logs.

webfrank commented 7 years ago

Hi, same thing with Kerlink, here is the gateway log:

Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: Disabling GPS mode for concentrator's counter... Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: host/sx1301 time offset=(1496857463s:801396µs) - drift=-5271µs Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: Enabling GPS mode for concentrator's counter. Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: [up] PUSH_ACK received in 70 ms Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: Received pkt from mote: 00000002 (fcnt=19) Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":1082899804,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":10.0,"rssi":-19,"size":15,"data":"QAIAAAAAEwAB0OkPnGYm"}]} Jun 7 18:02:26 klk-wifc-0300FE local1.notice spf: INFO: [up] PUSH_ACK received in 62 ms Jun 7 18:02:27 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[132:117] :) Jun 7 18:02:27 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":1083899804,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABEQAGo9MQ4A=="}} Jun 7 18:02:35 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 75 ms Jun 7 18:02:45 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 70 ms Jun 7 18:02:55 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 70 ms Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ##### 2017-06-07 18:02:56 GMT ##### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ### [UPSTREAM] ### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # RF packets received by concentrator: 1 Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00% Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # RF packets forwarded: 1 (15 bytes) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # PUSH_DATA datagrams sent: 2 (308 bytes) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # PUSH_DATA acknowledged: 100.00% Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ### [DOWNSTREAM] ### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # PULL_DATA sent: 3 (100.00% acknowledged) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # PULL_RESP(onse) datagrams received: 1 (174 bytes) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # RF packets sent to concentrator: 1 (13 bytes) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # TX errors: 0 Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # TX rejected (collision packet): 0.00% (req:17, rej:0) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # TX rejected (collision beacon): 0.00% (req:17, rej:0) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # TX rejected (too late): 0.00% (req:17, rej:0) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # TX rejected (too early): 0.00% (req:17, rej:0) Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # BEACON queued: 0 Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # BEACON sent so far: 0 Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # BEACON rejected: 0 Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ### [JIT] ### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: /home/jenkins/workspace/release_spf/lora_pkt_fwd/src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ### [GPS] ### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: # GPS sync is disabled Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: ##### END ##### Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: JSON up: {"stat":{"time":"2017-06-07 18:02:56 GMT","rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":1,"txnb":1}} Jun 7 18:02:56 klk-wifc-0300FE local1.notice spf: INFO: [up] PUSH_ACK received in 69 ms Jun 7 18:02:59 klk-wifc-0300FE local1.notice spf: INFO: Received pkt from mote: 00000002 (fcnt=20) Jun 7 18:02:59 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":1115688884,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":8.5,"rssi":-14,"size":15,"data":"QAIAAAAAFAABcAc+vMMr"}]} Jun 7 18:02:59 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[36:44] :) Jun 7 18:02:59 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":1116688884,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABEgAGuGB0xw=="}} Jun 7 18:03:05 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 71 ms Jun 7 18:03:15 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 68 ms Jun 7 18:03:25 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 71 ms Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ##### 2017-06-07 18:03:26 GMT ##### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ### [UPSTREAM] ### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # RF packets received by concentrator: 3 Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # CRC_OK: 33.33%, CRC_FAIL: 66.67%, NO_CRC: 0.00% Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # RF packets forwarded: 1 (15 bytes) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # PUSH_DATA datagrams sent: 2 (307 bytes) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # PUSH_DATA acknowledged: 50.00% Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ### [DOWNSTREAM] ### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # PULL_DATA sent: 3 (100.00% acknowledged) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # PULL_RESP(onse) datagrams received: 1 (174 bytes) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # RF packets sent to concentrator: 1 (13 bytes) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # TX errors: 0 Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # TX rejected (collision packet): 0.00% (req:18, rej:0) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # TX rejected (collision beacon): 0.00% (req:18, rej:0) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # TX rejected (too late): 0.00% (req:18, rej:0) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # TX rejected (too early): 0.00% (req:18, rej:0) Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # BEACON queued: 0 Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # BEACON sent so far: 0 Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # BEACON rejected: 0 Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ### [JIT] ### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: /home/jenkins/workspace/release_spf/lora_pkt_fwd/src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ### [GPS] ### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: # GPS sync is disabled Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: ##### END ##### Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: JSON up: {"stat":{"time":"2017-06-07 18:03:26 GMT","rxnb":3,"rxok":1,"rxfw":1,"ackr":50.0,"dwnb":1,"txnb":1}} Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: INFO: Disabling GPS mode for concentrator's counter... Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: INFO: host/sx1301 time offset=(1496857463s:796118µs) - drift=-5278µs Jun 7 18:03:26 klk-wifc-0300FE local1.notice spf: INFO: Enabling GPS mode for concentrator's counter. Jun 7 18:03:32 klk-wifc-0300FE local1.notice spf: INFO: Received pkt from mote: 00000002 (fcnt=21) Jun 7 18:03:32 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":1148932372,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":9.8,"rssi":-16,"size":15,"data":"QAIAAAAAFQABvFc7eXOA"}]} Jun 7 18:03:33 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[242:21] :) Jun 7 18:03:33 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":1149932372,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABEwAGnI1LIQ=="}} Jun 7 18:03:35 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 71 ms

Only one downlink sent, never received and pushed after every packer received.

Pulled latest docker image and same issue. I noticed on rxpk rfch=1 but on txpk is rfch=0. Don't know if it is correct.

gotthardp commented 7 years ago

Send me the new server log too, please.

The rxpk rfch and txpk rfch can be (and often are) different. The gateway would complain if this was wrong.

webfrank commented 7 years ago

Some more info. Today I switched on gateway and node, as usual after node sent data the GW tries to send:

Jun 9 05:47:17 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":71939668,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":9.5,"rssi":-19,"size":15,"data":"QAIAAAAAAgABEBrBFRI4"}]} Jun 9 05:47:18 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[210:199] :) Jun 9 05:47:18 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":72939668,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABBAAGWGYIJA=="}} Jun 9 05:47:19 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 339 ms Jun 9 05:47:29 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_ACK received in 69 ms

I tried to send a JSON with confirmed: false and it sent out:

Jun 9 05:50:37 klk-wifc-0300FE local1.notice spf: INFO: Received pkt from mote: 00000002 (fcnt=8) Jun 9 05:50:37 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":271518540,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":9.8,"rssi":-17,"size":15,"data":"QAIAAAAACAAByrQk8Vgk"}]} Jun 9 05:50:37 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[230:199] :) Jun 9 05:50:37 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":272518540,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":50,"data":"YAIAAAABCgAGAQDC1Y2gRtd2+LEI4QUdSRJ4n5BRRN5VGd6D/Hctf+zMJsEW6nIyNwo="}}

After that for every received packet I receive:

Jun 9 05:53:34 klk-wifc-0300FE local1.notice spf: JSON up: {"rxpk":[{"tmst":448360900,"chan":5,"rfch":1,"freq":868.100000,"stat":1,"modu":"LORA","datr":"SF7BW125","codr":"4/5","lsnr":9.8,"rssi":-19,"size":15,"data":"QAIAAAAAAwABVhKDokES"}]} Jun 9 05:53:34 klk-wifc-0300FE local1.notice spf: INFO: [down] PULL_RESP received - token[220:193] :) Jun 9 05:53:34 klk-wifc-0300FE local1.notice spf: JSON down: {"txpk":{"powe":14,"imme":false,"tmst":449360900,"codr":"4/5","datr":"SF7BW125","freq":868.1,"modu":"LORA","rfch":0,"ipol":true,"size":13,"data":"YAIAAAABBAAGWGYIJA=="}}

Here is the server log:

2017-06-09 03:48:57.614 [info] <0.259.0> gateway 00800000A0000DC2 {connected,{{151,54,172,90},32879}} 2017-06-09 05:46:08.806 [info] <0.259.0> gateway 7276FF00390300FE {connected,{{82,61,32,127},52402}} 2017-06-09 05:46:11.571 [debug] <0.7034.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:46:44.785 [debug] <0.7038.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:47:17.986 [debug] <0.7039.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:47:51.398 [debug] <0.7042.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:48:24.341 [debug] <0.7043.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:48:57.640 [debug] <0.7062.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:49:31.244 [debug] <0.7095.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:50:04.095 [debug] <0.7109.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:50:37.619 [debug] <0.7149.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:51:10.362 [debug] <0.7188.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:51:43.610 [debug] <0.7224.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:51:54.571 [debug] <0.7231.1>@lorawan_mac:check_link_fcnt:274 <<0,0,0,2>> fcnt reset 2017-06-09 05:51:54.571 [debug] <0.7231.1>@lorawan_mac:handle_uplink:383 DataRate <<0,0,0,2>> switched to dr 5 2017-06-09 05:51:54.571 [debug] <0.7231.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:52:27.777 [debug] <0.7261.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:53:00.688 [debug] <0.7274.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:53:34.404 [debug] <0.7280.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:54:07.520 [debug] <0.7281.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:54:40.461 [debug] <0.7329.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:55:14.166 [debug] <0.7342.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:55:47.470 [debug] <0.7351.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:56:20.776 [debug] <0.7355.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:56:53.994 [debug] <0.7359.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:57:27.485 [debug] <0.7366.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req] 2017-06-09 05:58:00.373 [debug] <0.7382.1>@lorawan_mac_commands:build_fopts:32 <<0,0,0,2>> <- [dev_status_req]

Does the default is confirmed: true? Downlink messages never expires? At the moment I cannot reset the database.

gotthardp commented 7 years ago

I do understand why the server is sending dev_status_req-- it's because the device didn't respond to this request. This is a correct behavior.

What is not a correct behavior is if the downlinks have the same FCnt. Do they? The frames listed above have weird FCnt numbers:

device sent FCnt=2, server replied with FCnt=4
device sent FCnt=4, server replied FCnt=10
then I saw a device restart happened
device sent FCnt=3, server replied FCnt=4

The repeated FCnt=4 is not necessarily wrong as there was a reset before.

Please, do the repeated downlinks from server look all the same (including FCnt) or not?

If the device sends different FCnt, but the server replies with the same FCnt, this is a bug. In such case, could you please git pull the latest master, try that again and send me the server logs? I made some debugging fixes to see how it works.

gotthardp commented 7 years ago

Because the gateway log you sent me before shows different FCnt, which is correct.

webfrank commented 7 years ago

Hi, I investigated further and decrypted the txpk using node lora-packet library:

MacBookPro:~ francesco$ node decode.js packet.toString()= Message Type = Data PHYPayload = 600200000001190006FD37810F ( PHYPayload = MHDR[1] | MACPayload[..] | MIC[4] ) MHDR = 60 MACPayload = 0200000001190006 MIC = FD37810F ( MACPayload = FHDR | FPort | FRMPayload ) FHDR = 0200000001190006 FPort = FRMPayload = ( FHDR = DevAddr[4] | FCtrl[1] | FCnt[2] | FOpts[0..15] ) DevAddr = 00000002 (Big Endian) FCtrl = 01 FCnt = 0019 (Big Endian) FOpts = 06 Message Type = Unconfirmed Data Down Direction = down FCnt = 25 FCtrl.ACK = false FCtrl.ADR = false packet MIC=fd37810f FRMPayload= MIC check=OK calculated MIC=fd37810f Decrypted='' MacBookPro:~ francesco$

It sends an empty payload. If I send some data from MQTT it got sent correct but the next rxpk will be replied with a txpk with empty payload.

gotthardp commented 7 years ago

But-- is the FCnt different in every downlink frame? Even the empty downlink frames shall have their FCnt increasing. Do they?

webfrank commented 7 years ago

Yes they are increasing

In data 9 giugno 2017 3:21:30 PM Petr Gotthard notifications@github.com ha scritto:

But-- is the FCnt different in every downlink frame? Even the empty downlink frames shall have their FCnt increasing. Do they?

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/gotthardp/lorawan-server/issues/118#issuecomment-307386728

gotthardp commented 7 years ago

But then everything works as expected ("it's not a bug, it's a feature"). The server sent a MAC command to the device requesting device status and didn't get a response, so it is re-transmitting the request in every frame. It will do that forever until it gets a response from the device.

Do you know why the device didn't respond? Did it get the downlink frame?

webfrank commented 7 years ago

Ok, it has a meaning now but the device does not reply to this command because lmic does not implement it.

Ok, could you put a check on node config to enable/disable this feature?

In data 9 giugno 2017 3:39:33 PM Petr Gotthard notifications@github.com ha scritto:

But then everything works as expected ("it's not a bug, it's a feature"). The server sent a MAC command to the device requesting device status and didn't get a response, so it is re-transmitting the request in every frame. It will do that forever until it gets a response from the device.

Do you know why the device didn't respond? Did it get the downlink frame?

-- You are receiving this because you authored the thread. Reply to this email directly or view it on GitHub: https://github.com/gotthardp/lorawan-server/issues/118#issuecomment-307391226

gotthardp commented 7 years ago

yes, i will make it configurable

webfrank commented 7 years ago

Thumb UP!

gotthardp commented 7 years ago

Should be done. Would you be able to test the latest master (either Docker or own build)?

gotthardp commented 7 years ago

Done in 0.4.5.

gotthardp / lorawan-server

How Downlinks are triggered? #118