debug websocket and downlink

[hallard]

Hi there, I'm using a Class C device (lopy) and websocket. I already used all that stuff without any problem but today I'm facing an issue that drive me crazy with downlink, websocket and nodered I got sample node red with 2 websockets (pylight in and pylight out) has follow the pylight (websocket) on the left is receiving data from device and the one on the right is to send downlink. LoRaWAN server is listening to localhost:8081

To try to understand my issue I made the inject payload function to minimal

msg.payload = {
    "time": "immediately",
    "devaddr": "0329E414",
    "port":1,
    "data": "016464640001"
}
return msg;

So all of this is sending a downlink to a device If I click on timestamp injector or if another node send data.

When I click on the timestamp node, the payload is sent to device with websocket and my node receive data, all is fine and node red debug show me correct things Now, if another node send data when I push on it button (so data is coming thru left pylight WS not from timestamp injector) node red debug shows the same data sent (makes sense, this is exactly what I expected) But my node never receive the downlink in this case, even if data out from inject payload function is the same. So I would like to know what's going on. Is WS is accepting data or not? If there any error I don't have? So my question is how to debug/know if JSON send to websocket (I repeat, it's the payload in both cases) is accepted? How can I see WS received/processed by the server?

Please note also that a strange issue (nothing related with this case), when I change

    "time": "immediately",

by a later date of course

   "time": "2018-08-08T21:05:30.2000",

I don't see the downlink queued in the admin console for the device. And of course downlink is not sent at the scheduled time.

Any hints ?

[gotthardp]

Could it be because after a node sent an uplink it is expecting Class A downlink and the Class C (immediately) transmission you triggered may collide with the receive windows opened for Class A?

[hallard]

Oh I forgot to mention, the node that send the uplink (class A) is not the same that receive the downlink (class C) But you’re right that’s a good point

[gotthardp]

The server shall print debug messages when something goes wrong. Is there something in the log files?

Concerning the second issue: I just found that packet_forwarder 4.0.0 uses a slightly different protocol that doesn't support the time field. What version of packet_forwarder are you running?

[hallard]

No, that's my problem the log file does not show strange things, but as I got 6 gateways, it's very verbose and hard to debug (didn't found any option to "disable" a GW) Anyway I would like to try to send the downlink let's say 3 sec later to see but I need the correct time format. The packet forwarder I'm using is a custom one based on legacy one https://github.com/ch2i/packet_forwarder and it's using the libloragw from here https://github.com/TheThingsNetwork/lora_gateway looks like version 4.0.0 What time format can I try?

[hallard]

You pointed me on the right direction, I traced log of packet forwarded on my GW (RPI3 + Ic880a) and guess what?

WARNING: [down] GPS disabled, impossible to send packet on specific UTC time, TX aborted

So the server has nothing to do, it's just my GW, I need to enable this mode even with no GPS ;-)

[gotthardp]

Yeah, the packet_forwarder documentation says the time-based scheduling works only with GPS.

[hallard]

Ok, based on your assumption I added a 3s delay between received packed and downlink so the RX windows from sending node is finished, so the flow looks like and I'm logging packet forwarder when I press on timestamp node red node 3s later I can see on packet forwarder log

Aug 08 12:11:40 ttn-gw04 loragw[32526]: INFO: [down] a packet will be sent in "immediate" mode

and my 2nd node is receiving downlink, so all is fine now when I press button on my first node, 3s later, the packet forwarder log this

Aug 08 12:11:44 ttn-gw04 loragw[32526]: INFO: [down] a packet will be sent on timestamp value 1008137028

So it's based on a timestamp, not like the other "immediate". Of course timestamp does not work because I do not have GPS but that's strange because the Node Red send the same payload to WebSocket pylight, see nodered debug window

Any idea why same payload comes to forwarder in different way?

[gotthardp]

This is weird. Do you have a log what really comes into the forwarder, please?

[hallard]

Sure since It's a custom version of packed forwarder I added a Log line to display JSON received

with timestamp injector in node red all is fine

Aug 08 14:04:55 ttn-gw04 loragw[476]: INFO: [down] for server myserver.com serv_addr[ic]PULL_RESP received :)
Aug 08 14:04:55 ttn-gw04 loragw[476]: INFO: [down] JSON received {"txpk":{"powe":16,"imme":true,"codr":"4/5","datr":"SF12BW125","freq":869.525,"modu":"LORA","rfch":0,"ipol":true,"size":19,"data":"YBTkKQMATAABSaiP8Cs7S0id/g=="}}
Aug 08 14:04:55 ttn-gw04 loragw[476]: INFO: [down] a packet will be sent in "immediate" mode

With my node push button, it's receiving a timestamp downlink, imme field is set to false.

Aug 08 14:02:08 ttn-gw04 loragw[476]: INFO: [down] for server myserver.com serv_addr[ic]PULL_RESP received :)
Aug 08 14:02:08 ttn-gw04 loragw[476]: INFO: [down] JSON received {"txpk":{"powe":16,"imme":false,"tmst":10558660,"codr":"4/5","datr":"SF12BW125","freq":867.5,"modu":"LORA","rfch":0,"ipol":true,"size":12,"data":"YDz3cQMgDgAWROlt"}}
Aug 08 14:02:08 ttn-gw04 loragw[476]: INFO: [down] a packet will be sent on timestamp value 10558660

would be interesting to know why websocket of lora server is not doing the same thing in both case?

[gotthardp]

There must be some silly typo somewhere. Could you double-check and compare the JSON data sent in both cases?

[hallard]

Done ton of time (and data is set and come from the same function inject payload so can't be different) but as I can't see what's arriving on LoRaWAN server it's difficult to compare

But what I've done is send data to another echo websocket (echo.websocket.org) and look and the answser

and in both case the answer of the echo websocket (output) is correct

[gotthardp]

So the structure is exactly the same, no errors/warnings what so ever but one sends class A and the other sends class C. I ran out of ideas :(

[hallard]

I've done another test, instead sending downlink packet with websocket, I send them with MQTT with the followin flow

Then I'm connecting with MQTTfx to see data and in both case the data is the same (makes sense I send the same)

Is there any option from the server to debug what's received and what is sent to the forwarder (connectors?), without this, it's difficult to see where is the issue. Could it be a field missing in the handler?

[hallard]

I digged into the code and found something interesting, I'm not a erlang coder but looks like this code part is interesting.

        fun ({_, undefined}, Acc) ->
                Acc;
            ({tmst, Time}, Acc) ->
                [{imme, false}, {tmst, Time} | Acc];
            ({time, immediately}, Acc) ->
                [{imme, true} | Acc];
            ({time, Time}, Acc) ->
                [{imme, false}, {time, iso8601:format(Time)} | Acc];
            ({region, _}, Acc) ->
                Acc; % internal parameter
            (Elem, Acc) -> [Elem | Acc]
        end,

I mean, may be in one case (data send by the node), there is somewhere a field tmst that has priority other the field time in the test condition that makes the downlink JSON data send a tmst and imme set to false instead of a imme field set to true

JSON received {"txpk":{"powe":16,"imme":false,"tmst":10558660,"codr":"4/5","datr":"SF12BW125","freq":867.5,"modu":"LORA","rfch":0,"ipol":true,"size":12,"data":"YDz3cQMgDgAWROlt"}}

JSON received {"txpk":{"powe":16,"imme":true,"codr":"4/5","datr":"SF12BW125","freq":869.525,"modu":"LORA","rfch":0,"ipol":true,"size":19,"data":"YBTkKQMATAABSaiP8Cs7S0id/g=="}}```

What do you think?

[gotthardp]

Your interpretation is correct, but you don't send any tmst, right?

[gotthardp]

Would you be able to build the server from sources? I could suggest you where to place a new log to see what the connector really sends.

[hallard]

Sure, I'm not sending any tmst, but I don't know how is working the hole process, I mean when the node send data, I'm pretty sure the GW add this tmst to the list and may be it's processed in the hole process and goes thru connectors and handlers, just an assumption. Anyway, I think I could build from source but do not have all on the machine since it's my production server so I'm not very confortable with this option. Is it complicated providing me a .deb package (or just the binary file)? It would be easier for me. I'm running latest stable 0.5.5 on debian X64

~$ cat /etc/debian_version
8.11
~$ uname -a
Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.51-2 (2017-12-03) x86_64 GNU/Linux
~$ l /usr/lib/lorawan-server/releases/
0.5.5/  RELEASES  start_erl.data

[hallard]

Hi Petr, Is there any possibility to have debug binary for testing this issue ? thanks

[gotthardp]

Alright. I made a 0.5.5 with additional logs. For download here: http://swimgate.eu/lorawan-server-0.5.5.tar.gz When you will generate the logs, please make sure there is a large interval between the two downlink messages and let me know which is which.

[hallard]

Hi, Thanks for providing me this.

I started some investigations, and after being flooded by send message of the node I tested another one custom basic and guess what, it's working fine.

So the node I was trying is a RAK Wireless Lora Button, It's nice but firmware is a pain, first you need to press once and it's doing join, after that no frame is sent to indicate button you pressed. You need to press another time the button to see frame coming but you have very limited time before the button goes to sleep and repeat join process again. And moreover you can't disable confirmed packed nor ADR. So from my point of view it's a really nice useless device.

Anyway, after investigation, the first downlink (the good one) is sent by server, but immediately after (300ms) another one is send with ime set to false, and I suspect it's for confirmed and/or ADR check log at 19:27:08, but may be the 2nd downlink override the first and that why the device does not receive it. As you talked earlier I should postpose the downlink for 2s to see but as my GW do not have GPS I can't do that because timestamped downlink are not supported.

Here is the log for reference

2018-08-29 19:27:09.185 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 5,codr => <<"4/5">>,data => <<"gDz3cQOAAgAIAJAP8ntig4OyNkBG">>,datr => <<"SF12BW125">>,freq => 867.5,lsnr => 8.2,modu => <<"LORA">>,rfch => 0,rssi => -69,size => 21,stat => 1,time => <<"2018-08-29T17:27:09.115990Z">>,tmst => 3874985836}]}
2018-08-29 19:27:09.186 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 5,codr => <<"4/5">>,data => <<"gDz3cQOAAgAIAJAP8ntig4OyNkBG">>,datr => <<"SF12BW125">>,freq => 867.5,lsnr => 8.2,modu => <<"LORA">>,rfch => 0,rssi => -60,size => 21,stat => 1,time => <<"2018-08-29T17:27:09.116366Z">>,tmst => 443807932}]}
2018-08-29 19:27:09.389 [debug] <0.297.0>@lorawan_application_backend:handle_downlink:174 handle_downlink <<"ch2i-pylight">> #{data => <<2,100,100,100,0,1>>,devaddr => <<3,94,195,81>>,port => 1,time => immediately}
2018-08-29 19:27:09.389 [debug] <0.284.0>@lorawan_gw_router:handle_cast:93 <-- freq 869.525, datr SF12BW125, codr 4/5, tmst undefined, size 19
2018-08-29 19:27:09.389 [debug] <0.285.0>@lorawan_gw_forwarder:handle_cast:41 <--- [{txpk,[{powe,16},{imme,true},{codr,<<"4/5">>},{datr,<<"SF12BW125">>},{freq,869.525},{modu,<<"LORA">>},{rfch,0},{ipol,true},{size,19},{data,<<"YFHDXgMAYgMBcMFr4UJfDbQPLQ==">>}]}]
2018-08-29 19:27:09.638 [debug] <0.284.0>@lorawan_gw_router:handle_cast:93 <-- freq 867.5, datr SF12BW125, codr 4/5, tmst 444807932, size 12
2018-08-29 19:27:09.639 [debug] <0.285.0>@lorawan_gw_forwarder:handle_cast:41 <--- [{txpk,[{powe,16},{imme,false},{tmst,444807932},{codr,<<"4/5">>},{datr,<<"SF12BW125">>},{freq,867.5},{modu,<<"LORA">>},{rfch,0},{ipol,true},{size,12},{data,<<"YDz3cQMgAwBuflZa">>}]}]
2018-08-29 19:27:11.537 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 1,codr => <<"4/5">>,data => <<"AAUBABCC1bNwKwwAYDLVs3CRIKytqTI=">>,datr => <<"SF7BW125">>,freq => 868.3,lsnr => -3.2,modu => <<"LORA">>,rfch => 1,rssi => -111,size => 23,stat => 1,time => <<"2018-08-29T17:27:11.495767Z">>,tmst => 3439415563}]}
2018-08-29 19:27:12.468 [warning] <0.284.0> gateway FCC23DFFFE0F44B5 {ack_lost,33.3}
2018-08-29 19:27:14.160 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 2,codr => <<"4/5">>,data => <<"AAABABCC1bNwrAsAYDLVs3A+uBXHSQU=">>,datr => <<"SF7BW125">>,freq => 868.5,lsnr => 2.5,modu => <<"LORA">>,rfch => 1,rssi => -107,size => 23,stat => 1,time => <<"2018-08-29T17:27:14.118531Z">>,tmst => 3442052627}]}
2018-08-29 19:27:16.932 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 0,codr => <<"4/5">>,data => <<"AAABABCC1bNwHAwAYDLVs3ADZbxifwI=">>,datr => <<"SF7BW125">>,freq => 868.1,lsnr => -7.0,modu => <<"LORA">>,rfch => 1,rssi => -115,size => 23,stat => 1,time => <<"2018-08-29T17:27:16.891388Z">>,tmst => 3444818979}]}
2018-08-29 19:27:17.727 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 0.0,alti => 110,desc => <<"CH2i TTN Gateway 02">>,dwnb => 0,lati => 46.62585,long => 0.43493,mail => <<"contact@ch2i.eu">>,pfrm => <<"IMST + Rpi">>,rxfw => 0,rxnb => 0,rxok => 0,time => <<"2018-08-29 17:27:17 GMT">>,txnb => 0}}
2018-08-29 19:27:19.772 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 1,codr => <<"4/5">>,data => <<"AAUBABCC1bNwKwwAYDLVs3A/wZHPM6w=">>,datr => <<"SF7BW125">>,freq => 868.3,lsnr => -2.5,modu => <<"LORA">>,rfch => 1,rssi => -113,size => 23,stat => 1,time => <<"2018-08-29T17:27:19.724342Z">>,tmst => 3447656803}]}
2018-08-29 19:27:22.579 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 5,codr => <<"4/5">>,data => <<"QAP13UkAAAACaRn5xpG60u+poijezxdS0iNlr1tgp7axfmcMac3s7NjSndP32g==">>,datr => <<"SF12BW125">>,freq => 867.5,lsnr => 2.5,modu => <<"LORA">>,rfch => 0,rssi => -106,size => 46,stat => 1,time => <<"2018-08-29T17:27:22.537342Z">>,tmst => 3450425428}]}
2018-08-29 19:27:24.166 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 100.0,desc => <<"CH2i loragw-0007 IMST Lora Lite">>,dwnb => 3,mail => <<>>,pfrm => <<"IMST + Rpi">>,rxfw => 2,rxnb => 2,rxok => 2,time => <<"2018-08-29 17:27:24 GMT">>,txnb => 3}}
2018-08-29 19:27:24.951 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 1,codr => <<"4/5">>,data => <<"AAABABCC1bNwHwwAYDLVs3CurVf7jR0=">>,datr => <<"SF7BW125">>,freq => 868.3,lsnr => 2.0,modu => <<"LORA">>,rfch => 1,rssi => -109,size => 23,stat => 1,time => <<"2018-08-29T17:27:24.909752Z">>,tmst => 3452824299}]}
2018-08-29 19:27:26.700 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 100.0,alti => 102,desc => <<"CH2i loragw-0004 PI3 iC880a">>,dwnb => 1,lati => 46.65761,long => 0.36505,mail => <<"contact@ch2i.eu">>,pfrm => <<"IMST + Rpi">>,rxfw => 1,rxnb => 2,rxok => 1,time => <<"2018-08-29 17:27:26 GMT">>,txnb => 1}}
2018-08-29 19:27:31.108 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 4,codr => <<"4/5">>,data => <<"gHeEuUiAAAAC1cURSwBbfSDn21TyMmwqyOyXPa9aSQ==">>,datr => <<"SF7BW125">>,freq => 867.3,lsnr => -1.5,modu => <<"LORA">>,rfch => 0,rssi => -112,size => 31,stat => 1,time => <<"2018-08-29T17:27:31.066225Z">>,tmst => 3458989611}]}
2018-08-29 19:27:39.307 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 1,codr => <<"4/5">>,data => <<"AAkBABCC1bNwBgwAYDLVs3CTz10pvtc=">>,datr => <<"SF7BW125">>,freq => 868.3,lsnr => -7.2,modu => <<"LORA">>,rfch => 1,rssi => -115,size => 23,stat => 1,time => <<"2018-08-29T17:27:39.264726Z">>,tmst => 3467190891}]}
2018-08-29 19:27:40.818 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 5,codr => <<"4/5">>,data => <<"QE4lASYAcpMfn44rahILqaeqrFaNitTsgQ==">>,datr => <<"SF7BW125">>,freq => 867.5,lsnr => 7.0,modu => <<"LORA">>,rfch => 0,rssi => -57,size => 25,stat => 1,time => <<"2018-08-29T17:27:40.683644Z">>,tmst => 386603852}]}
2018-08-29 19:27:42.460 [warning] <0.284.0> gateway FCC23DFFFE0F44B5 {ack_lost,33.3}
2018-08-29 19:27:47.717 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 0.0,alti => 110,desc => <<"CH2i TTN Gateway 02">>,dwnb => 0,lati => 46.62585,long => 0.43493,mail => <<"contact@ch2i.eu">>,pfrm => <<"IMST + Rpi">>,rxfw => 1,rxnb => 1,rxok => 1,time => <<"2018-08-29 17:27:47 GMT">>,txnb => 0}}
2018-08-29 19:27:47.718 [warning] <0.284.0> gateway 0002B827EBD5E2E2 {ack_lost,100.0}
2018-08-29 19:27:50.659 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 7,codr => <<"4/5">>,data => <<"QLAlASYAAi8BnUvcrOIDZNWUINCH">>,datr => <<"SF7BW125">>,freq => 867.9,lsnr => 8.8,modu => <<"LORA">>,rfch => 0,rssi => 1,size => 21,stat => 1,time => <<"2018-08-29T17:27:50.571606Z">>,tmst => 396483900}]}
2018-08-29 19:27:53.888 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 2,codr => <<"4/6">>,data => <<"AgAAAgBbRwz2vS5cP0SGaQbENaM=">>,datr => <<"SF12BW125">>,freq => 868.5,lsnr => -10.5,modu => <<"LORA">>,rfch => 1,rssi => -107,size => 20,stat => 1,time => <<"2018-08-29T17:27:53.832240Z">>,tmst => 488520468}]}
2018-08-29 19:27:53.889 [debug] <0.1322.0>@lorawan_mac:ingest_frame0:59 Unknown frame: <<2,0,0,2,0,91,71,12,246,189,46,92,63,68,134,105>>
2018-08-29 19:27:53.889 [error] <0.1322.0> server unknown_frame
2018-08-29 19:27:53.897 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 2,codr => <<"4/6">>,data => <<"AgAAAgBbRwz2vS5cP0SGaQbENaM=">>,datr => <<"SF12BW125">>,freq => 868.5,lsnr => -9.8,modu => <<"LORA">>,rfch => 1,rssi => -101,size => 20,stat => 1,time => <<"2018-08-29T17:27:53.835825Z">>,tmst => 3919698372}]}
2018-08-29 19:27:54.167 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 100.0,desc => <<"CH2i loragw-0007 IMST Lora Lite">>,dwnb => 0,mail => <<>>,pfrm => <<"IMST + Rpi">>,rxfw => 1,rxnb => 1,rxok => 1,time => <<"2018-08-29 17:27:54 GMT">>,txnb => 0}}
2018-08-29 19:27:55.414 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{rxpk => [#{chan => 6,codr => <<"4/5">>,data => <<"QGsuASYAnC8BSSgyB5gXEuhpOhVH">>,datr => <<"SF7BW125">>,freq => 867.7,lsnr => 9.0,modu => <<"LORA">>,rfch => 0,rssi => -1,size => 21,stat => 1,time => <<"2018-08-29T17:27:55.327309Z">>,tmst => 401240668}]}
2018-08-29 19:27:56.685 [debug] <0.285.0>@lorawan_gw_forwarder:handle_info:56 ---> #{stat => #{ackr => 100.0,alti => 102,desc => <<"CH2i loragw-0004 PI3 iC880a">>,dwnb => 0,lati => 46.65761,long => 0.36505,mail => <<"contact@ch2i.eu">>,pfrm => <<"IMST + Rpi">>,rxfw => 1,rxnb => 1,rxok => 1,time => <<"2018-08-29 17:27:56 GMT">>,txnb => 0}}

[gotthardp]

Forgive my ignorance, but--- the log contains only one backend-triggered downlink.

You should generate two backends, each using the different method so we can compare for differences, or?

Petr

[gotthardp]

Some info: the packet_forwarder (at lest the newer versions) is able to schedule the Class C transmissions in the next idle slot. It however cannot know when a device is listening for Class A downlink, so if a Class C is triggered just after Class A (for the same device), the Class C may not be received.

I will (for 0.6.0) implement a small check and delay Class C if a Class A was just received. This may fix your trouble.

[gotthardp]

The 0.6.0 is out. Please check if the problem was solved and let me know if not.

[hallard]

@gotthardp I don't know know if the changes made it, but with 0.6.1 as we can see downlink it helps to troubleshot. My device was sending an uplink an immediately a donwlink was sent to this device. Of course it has priority on the other downlink I wanted to send to the class C device. I searched why a downlink was sent immediately and found. I had disable ADR so it was not this one but Status request was set to Yes and when I disabled status request (FYI device sending have LMIC stack) things worked as expected. After that I enabled back Status Request to look at your change (delay class C device) , as you can see below, the Class C device downlink is not delayed but I suspect device is not seen as class C

How can I check device class in your server? can I force it somewhere? The device is a Lopy initialized as a class C as follow.

LoRa(mode=LoRa.LORAWAN, public=True, tx_retries=3, device_class=LoRa.CLASS_C)

[gotthardp]

It should have worked even with the Status request set to Yes. I'd need more logs to debug this, but your solution will work as well. The server doesn't distinguish between class A and class C. When requested, it tries to send class C to everyone.

[gotthardp]

Hello. There was one more bug in 0.6.1, which got fixed in the just released 0.6.2. I believe the issue should be fixed now. Please open a new issue if it persists in 0.6.2.