search

Azure / iotedge-lorawan-starterkit

Sample implementation of LoRaWAN components to connect LoRaWAN antenna gateway running IoT Edge directly with Azure IoT.
https://azure.github.io/iotedge-lorawan-starterkit/2.2.1
Other
183 stars 60 forks source link

Question: Response message from Class C direct message? #194

Closed gerfen closed 5 years ago

gerfen commented 5 years ago

My class C devices have the ability to send a response message after receiving a direct message. For example:

image

Currently the returned payload from my successful calls are null. 

{"status":200,"payload":null}

Is this scenario supported in the currently release?

ronniesa commented 5 years ago

The Class C device will either send an ACK or upstream message so you will see it as device message and not as return of the direct method call "{"status":200,"payload":null}". The reason is that the device can take the time that it needs to process and the ack back or send a upstream message with the payload. You can specify a messagId in the payload that you can use as correlation: https://github.com/Azure/iotedge-lorawan-starterkit/blob/master/Docs/Pictures/cloudtodevice-classc.png

gerfen commented 5 years ago

@ronniesa - that makes sense. I'm seeing intermittent upstream messages from the class C device as shown here[1]. I'm not sure if this is due to a further frequency issue related to US frequencies or if there is an issue with the device? I'm currently talking with the device manufacturer to understand the behavior. I'd like to leave this issue open for a few more days until I hear back from the manufacturer. Is that OK?

[1] Gateway logs
2019-06-20 17:12:43.601 Statistic: {"stat":{"time":"2019-06-20 17:12:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:12:55.375 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!1","MessageId":"53be5fb4c6bc48ef9031032a26db86d1"}  Command to set DO to high
2019-06-20 17:12:55.375 1152612292133022: [class-c] down frame counter: 19
2019-06-20 17:12:55.376 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAEwA3T5wTGAPYkvUhXt6QoT1wciBy3Q==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:12:55.376 UDP: sending message with ID A3CA, to 172.18.0.1:58495
2019-06-20 17:12:55.377 UDP: message sent with ID A3CA
2019-06-20 17:12:55.378 UDP: packet with id A3CA successfully transmitted by the aggregator
2019-06-20 17:13:13.596 Statistic: {"stat":{"time":"2019-06-20 17:13:13 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:13:43.600 Statistic: {"stat":{"time":"2019-06-20 17:13:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:14:13.600 Statistic: {"stat":{"time":"2019-06-20 17:14:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:14:43.595 Statistic: {"stat":{"time":"2019-06-20 17:14:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:15:13.604 Statistic: {"stat":{"time":"2019-06-20 17:15:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:15:43.596 Statistic: {"stat":{"time":"2019-06-20 17:15:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:16:13.599 Statistic: {"stat":{"time":"2019-06-20 17:16:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:16:22.435 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!0","MessageId":"f866120bd2924af885e4b1eb146b8b92"} 
2019-06-20 17:16:22.437 1152612292133022: [class-c] down frame counter: 20
2019-06-20 17:16:22.438 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAFAA3Rw4vmScDw/QwpW59jF4031q27w==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:16:22.438 UDP: sending message with ID 5FF0, to 172.18.0.1:58495
2019-06-20 17:16:22.438 UDP: message sent with ID 5FF0
2019-06-20 17:16:22.441 UDP: packet with id 5FF0 successfully transmitted by the aggregator
2019-06-20 17:16:43.600 Statistic: {"stat":{"time":"2019-06-20 17:16:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:17:13.602 Statistic: {"stat":{"time":"2019-06-20 17:17:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:17:43.375 Physical dataUp {"rxpk":[{"tmst":304396796,"chan":2,"rfch":0,"freq":902.700000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":8.2,"rssi":-49,"size":96,"data":"QJ1c+gIAigA3efE0qYSlbS1ryVENDIiFTI3ff0WFpD8WWjYsYaAVZ7R9cPh6jIcAphOVmmxXalHCrV38+x60EOvW2QC0dVLlaH9Ck2TlAE8PLLqU5EbEKVHlXFmdWlT/"}]}
2019-06-20 17:17:43.376 1152612292133022: device in cache
2019-06-20 17:17:43.377 1152612292133022: converted 16bit FCnt 138 to 32bit FCnt 138
2019-06-20 17:17:43.377 1152612292133022: valid frame counter, msg: 138 server: 118
2019-06-20 17:17:43.377 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:17:43.378 1152612292133022: sending message {"time":null,"tmms":0,"tmst":304396796,"freq":902.7,"chan":2,"rfch":0,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-49,"lsnr":8.2,"size":96,"data":{"value":"fvRTALW/C10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="},"port":55,"fcnt":138,"rawdata":"fvRTALW/C10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4=","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051063374} to hub
2019-06-20 17:17:43.407 1152612292133022: message '{"value":"fvRTALW/C10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="}' sent to hub 
2019-06-20 17:17:43.408 1152612292133022: checking cloud to device message for 00:00:00.5664509
2019-06-20 17:17:43.603 Statistic: {"stat":{"time":"2019-06-20 17:17:43 GMT","rxnb":2,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:17:43.978 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:17:43.979 1152612292133022: updating twin
2019-06-20 17:17:43.992 1152612292133022: twin updated
2019-06-20 17:17:43.992 1152612292133022: processing time: 00:00:00.6180634
2019-06-20 17:18:13.601 Statistic: {"stat":{"time":"2019-06-20 17:18:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:18:27.896 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!1","MessageId":"ce21f04393fe46cb93dd68f66650b4ff"} 
2019-06-20 17:18:27.896 1152612292133022: [class-c] down frame counter: 21
2019-06-20 17:18:27.896 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAFQA3VXk9y5uO8H1sVYs6Ui29Pet2OQ==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:18:27.897 UDP: sending message with ID 6FA7, to 172.18.0.1:58495
2019-06-20 17:18:27.897 UDP: message sent with ID 6FA7
2019-06-20 17:18:27.899 UDP: packet with id 6FA7 successfully transmitted by the aggregator
2019-06-20 17:18:43.605 Statistic: {"stat":{"time":"2019-06-20 17:18:43 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:19:43.604 Statistic: {"stat":{"time":"2019-06-20 17:19:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:20:13.602 Statistic: {"stat":{"time":"2019-06-20 17:20:13 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:20:43.601 Statistic: {"stat":{"time":"2019-06-20 17:20:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:21:12.276 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!0","MessageId":"527df024f2794e59b0bd6c2d331de160"} 
2019-06-20 17:21:12.276 1152612292133022: [class-c] down frame counter: 22
2019-06-20 17:21:12.277 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAFgA374aIc8KaPGfceGfDd8qNKu7UyA==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:21:12.277 UDP: sending message with ID DFF9, to 172.18.0.1:58495
2019-06-20 17:21:12.277 UDP: message sent with ID DFF9
2019-06-20 17:21:12.280 UDP: packet with id DFF9 successfully transmitted by the aggregator
2019-06-20 17:21:13.611 Statistic: {"stat":{"time":"2019-06-20 17:21:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:21:18.878 Physical dataUp {"rxpk":[{"tmst":519905284,"chan":5,"rfch":1,"freq":903.300000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":12.5,"rssi":-55,"size":24,"data":"QJ1c+gIAkQA32jExbFZGnSm2yw68BP9R"}]}
2019-06-20 17:21:18.879 1152612292133022: device in cache
2019-06-20 17:21:18.879 1152612292133022: converted 16bit FCnt 145 to 32bit FCnt 145
2019-06-20 17:21:18.880 1152612292133022: valid frame counter, msg: 145 server: 138
2019-06-20 17:21:18.880 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:21:18.880 1152612292133022: sending message {"time":null,"tmms":0,"tmst":519905284,"freq":903.3,"chan":5,"rfch":1,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-55,"lsnr":12.5,"size":24,"data":{"value":"fvILAIfAC10AAH4="},"port":55,"fcnt":145,"rawdata":"fvILAIfAC10AAH4=","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051278877} to hub
2019-06-20 17:21:18.907 1152612292133022: message '{"value":"fvILAIfAC10AAH4="}' sent to hub 
2019-06-20 17:21:18.907 1152612292133022: checking cloud to device message for 00:00:00.5705192
2019-06-20 17:21:19.478 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:21:19.478 1152612292133022: processing time: 00:00:00.6011908
2019-06-20 17:21:43.607 Statistic: {"stat":{"time":"2019-06-20 17:21:43 GMT","rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:22:13.611 Statistic: {"stat":{"time":"2019-06-20 17:22:13 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:22:40.176 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!1","MessageId":"fb6f2511453843d9aa791889bda8ac33"} 
2019-06-20 17:22:40.176 1152612292133022: [class-c] down frame counter: 23
2019-06-20 17:22:40.183 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAFwA3x0rFVNuRIz15ctNmhoFukGdrKw==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:22:40.183 UDP: sending message with ID A59F, to 172.18.0.1:58495
2019-06-20 17:22:40.184 UDP: message sent with ID A59F
2019-06-20 17:22:40.184 UDP: packet with id A59F successfully transmitted by the aggregator
2019-06-20 17:22:43.611 Statistic: {"stat":{"time":"2019-06-20 17:22:43 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:22:46.721 Physical dataUp {"rxpk":[{"tmst":607742380,"chan":2,"rfch":0,"freq":902.700000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":9.0,"rssi":-55,"size":28,"data":"QJ1c+gIAlQA3JpEVyJpw2iLQ7zJN8/tZPZMYHA=="}]}
2019-06-20 17:22:46.722 1152612292133022: device in cache
2019-06-20 17:22:46.723 1152612292133022: converted 16bit FCnt 149 to 32bit FCnt 149
2019-06-20 17:22:46.723 1152612292133022: valid frame counter, msg: 149 server: 145
2019-06-20 17:22:46.723 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:22:46.723 1152612292133022: sending message {"time":null,"tmms":0,"tmst":607742380,"freq":902.7,"chan":2,"rfch":0,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-55,"lsnr":9.0,"size":28,"data":{"value":"ZGlnaXRhbE91dHB1dCEx"},"port":55,"fcnt":149,"rawdata":"ZGlnaXRhbE91dHB1dCEx","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051366720} to hub
2019-06-20 17:22:46.754 1152612292133022: message '{"value":"ZGlnaXRhbE91dHB1dCEx"}' sent to hub 
2019-06-20 17:22:46.754 1152612292133022: checking cloud to device message for 00:00:00.5668446
2019-06-20 17:22:47.321 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:22:47.321 1152612292133022: updating twin
2019-06-20 17:22:47.331 1152612292133022: twin updated
2019-06-20 17:22:47.332 1152612292133022: processing time: 00:00:00.6111020
2019-06-20 17:23:13.608 Statistic: {"stat":{"time":"2019-06-20 17:23:13 GMT","rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:23:43.605 Statistic: {"stat":{"time":"2019-06-20 17:23:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:24:13.613 Statistic: {"stat":{"time":"2019-06-20 17:24:13 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:24:16.749 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!0","MessageId":"fa6310e3afee4ada87a78ef243513a03"}
2019-06-20 17:24:16.751 1152612292133022: [class-c] down frame counter: 24
2019-06-20 17:24:16.752 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAGAA38uSnmE5am/Xs6HaMnD+gD9jYOw==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:24:16.753 UDP: sending message with ID 433C, to 172.18.0.1:58495
2019-06-20 17:24:16.753 UDP: message sent with ID 433C
2019-06-20 17:24:16.755 UDP: packet with id 433C successfully transmitted by the aggregator
2019-06-20 17:24:43.614 Statistic: {"stat":{"time":"2019-06-20 17:24:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:24:58.214 Physical dataUp {"rxpk":[{"tmst":739241332,"chan":3,"rfch":0,"freq":902.900000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":11.8,"rssi":-71,"size":96,"data":"QJ1c+gIAmwA3eyKSUcVnvBy/giWaUnJyr6I9ZAmxhTrvkFieDHTp/wnXOTSsYIxQUIQiejy3cECMsceUIlJbdQgEPZU46oJ3CFo5KeIcN8nWrH2YrEFYMZxp3tEOUWLy"}]}
2019-06-20 17:24:58.215 1152612292133022: device in cache
2019-06-20 17:24:58.216 1152612292133022: converted 16bit FCnt 155 to 32bit FCnt 155
2019-06-20 17:24:58.216 1152612292133022: valid frame counter, msg: 155 server: 149
2019-06-20 17:24:58.216 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:24:58.217 1152612292133022: sending message {"time":null,"tmms":0,"tmst":739241332,"freq":902.9,"chan":3,"rfch":0,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-71,"lsnr":11.8,"size":96,"data":{"value":"fvRTAGjBC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="},"port":55,"fcnt":155,"rawdata":"fvRTAGjBC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4=","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051498213} to hub
2019-06-20 17:24:58.244 1152612292133022: message '{"value":"fvRTAGjBC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="}' sent to hub 
2019-06-20 17:24:58.245 1152612292133022: checking cloud to device message for 00:00:00.5684389
2019-06-20 17:24:58.814 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:24:58.815 1152612292133022: processing time: 00:00:00.6019045
2019-06-20 17:25:13.616 Statistic: {"stat":{"time":"2019-06-20 17:25:13 GMT","rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:25:43.609 Statistic: {"stat":{"time":"2019-06-20 17:25:43 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:26:13.613 Statistic: {"stat":{"time":"2019-06-20 17:26:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:26:24.549 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!1","MessageId":"90ddf92b9e464483b80fa0ac4f823da0"} 
2019-06-20 17:26:24.549 1152612292133022: [class-c] down frame counter: 25
2019-06-20 17:26:24.549 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAGQA3a7GHS0U4s+61C/RW4h0CMxkKOw==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:26:24.550 UDP: sending message with ID C774, to 172.18.0.1:58495
2019-06-20 17:26:24.550 UDP: message sent with ID C774
2019-06-20 17:26:24.556 UDP: packet with id C774 successfully transmitted by the aggregator
2019-06-20 17:26:25.125 Physical dataUp {"rxpk":[{"tmst":826145404,"chan":0,"rfch":0,"freq":902.300000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":12.2,"rssi":-60,"size":96,"data":"QJ1c+gIAnAA3lyHLQ9Yty8M9Hd0k763Mqkd7VRKNUuqGwDMHj4VfQP71PVoxZa0iZFXndT7ZWCk0f+dSjp5cd+aDeifhSc90qnP+Dj3PgHX9epFlsvMJgRRCG8+HdHNE"}]}
2019-06-20 17:26:25.127 1152612292133022: device in cache
2019-06-20 17:26:25.127 1152612292133022: converted 16bit FCnt 156 to 32bit FCnt 156
2019-06-20 17:26:25.127 1152612292133022: valid frame counter, msg: 156 server: 155
2019-06-20 17:26:25.128 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:26:25.128 1152612292133022: sending message {"time":null,"tmms":0,"tmst":826145404,"freq":902.3,"chan":0,"rfch":0,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-60,"lsnr":12.2,"size":96,"data":{"value":"fvRTAL7BC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="},"port":55,"fcnt":156,"rawdata":"fvRTAL7BC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4=","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051585124} to hub
2019-06-20 17:26:25.157 1152612292133022: message '{"value":"fvRTAL7BC10AAAAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="}' sent to hub 
2019-06-20 17:26:25.157 1152612292133022: checking cloud to device message for 00:00:00.5674412
2019-06-20 17:26:25.725 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:26:25.725 1152612292133022: processing time: 00:00:00.6010423
2019-06-20 17:26:43.613 Statistic: {"stat":{"time":"2019-06-20 17:26:43 GMT","rxnb":1,"rxok":1,"rxfw":1,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:27:13.619 Statistic: {"stat":{"time":"2019-06-20 17:27:13 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:27:37.836 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!0","MessageId":"6f653db23bdb480a9c409dc4f80b48ec"} 
2019-06-20 17:27:37.836 1152612292133022: [class-c] down frame counter: 26
2019-06-20 17:27:37.837 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAGgA3I/IS/pwu6Qe9qg6zv/6AOLl0xA==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:27:37.837 UDP: sending message with ID A7D9, to 172.18.0.1:58495
2019-06-20 17:27:37.838 UDP: message sent with ID A7D9
2019-06-20 17:27:37.839 UDP: packet with id A7D9 successfully transmitted by the aggregator
2019-06-20 17:27:43.617 Statistic: {"stat":{"time":"2019-06-20 17:27:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:28:13.614 Statistic: {"stat":{"time":"2019-06-20 17:28:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:28:43.620 Statistic: {"stat":{"time":"2019-06-20 17:28:43 GMT","rxnb":2,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:29:13.613 Statistic: {"stat":{"time":"2019-06-20 17:29:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:29:43.622 Statistic: {"stat":{"time":"2019-06-20 17:29:43 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:30:07.130 1152612292133022: received cloud to device message from direct method: {"devEUI":"1152612292133022","fport":"55","confirmed":true,"payload":"digitalOutput!1","MessageId":"f6afdd8264b9442ea526d87f0908ef8f"}
2019-06-20 17:30:07.130 1152612292133022: [class-c] down frame counter: 27
2019-06-20 17:30:07.131 1152612292133022: ConfirmedDataDown {"txpk":{"imme":true,"data":"oJ1c+gIAGwA3LfW8Z5BzRoaaN29g2C8mIi4b2Q==","tmst":0,"size":28,"freq":923.3,"rfch":0,"modu":"LORA","datr":"SF10BW500","codr":"4/5","powe":14,"ipol":true}}
2019-06-20 17:30:07.131 UDP: sending message with ID 3AF1, to 172.18.0.1:58495
2019-06-20 17:30:07.132 UDP: message sent with ID 3AF1
2019-06-20 17:30:07.135 UDP: packet with id 3AF1 successfully transmitted by the aggregator
2019-06-20 17:30:13.618 Statistic: {"stat":{"time":"2019-06-20 17:30:13 GMT","rxnb":0,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":1,"txnb":1}}
2019-06-20 17:30:43.623 Statistic: {"stat":{"time":"2019-06-20 17:30:43 GMT","rxnb":1,"rxok":0,"rxfw":0,"ackr":100.0,"dwnb":0,"txnb":0}}
2019-06-20 17:30:46.094 Physical dataUp {"rxpk":[{"tmst":1087117564,"chan":4,"rfch":1,"freq":903.100000,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","lsnr":11.8,"rssi":-55,"size":96,"data":"QJ1c+gIAqAA3ymJYJa24tV4LetIOAGGTtVav0/7ajcKC/+uVVBSowlGrrLBuHl9OYdAc5qBqoHYaA92ayz2hyrJkeayTssg50Tlk59cdlUtIOM8LVDlqWqryd9842ybS"}]}
2019-06-20 17:30:46.095 1152612292133022: device in cache
2019-06-20 17:30:46.096 1152612292133022: converted 16bit FCnt 168 to 32bit FCnt 168
2019-06-20 17:30:46.096 1152612292133022: valid frame counter, msg: 168 server: 156
2019-06-20 17:30:46.097 1152612292133022: no decoder set in device twin. port: 55
2019-06-20 17:30:46.097 1152612292133022: sending message {"time":null,"tmms":0,"tmst":1087117564,"freq":903.1,"chan":4,"rfch":1,"stat":1,"modu":"LORA","datr":"SF8BW125","codr":"4/5","rssi":-55,"lsnr":11.8,"size":96,"data":{"value":"fvRTAMPCC10AAQAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="},"port":55,"fcnt":168,"rawdata":"fvRTAMPCC10AAQAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4=","eui":"1152612292133022","gatewayid":"evolution-gateway","edgets":1561051846093} to hub
2019-06-20 17:30:46.125 1152612292133022: message '{"value":"fvRTAMPCC10AAQAeAAAAAwEBAQAeAAAAAgIAAgAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAAAeAAAAAAAAAH4="}' sent to hub 
2019-06-20 17:30:46.125 1152612292133022: checking cloud to device message for 00:00:00.5674510
2019-06-20 17:30:46.694 1152612292133022: done checking cloud to device message, found no message
2019-06-20 17:30:46.694 1152612292133022: updating twin
2019-06-20 17:30:46.706 1152612292133022: twin updated
2019-06-20 17:30:46.706 1152612292133022: processing time: 00:00:00.6131619
ronniesa commented 5 years ago

Yes you can keep it open. Upstream should not be a problem for our stack between frequencies (e.g. US vs EU). If the PktFwr is correctly configured all the freq stuff is done by the device and the pktfwrd….. in our stack we just get what the pktfwrd is sending us.... downstream is another story because we need to prepare the msg with the correct DR, freq, etc...

gerfen commented 5 years ago

@ronniesa I'm still having issues getting consistent upstream messages from the Class C devices in response to a downstream message. I started monitoring the packet forwarder logs and I'm seeing this...

  1. When a message is successfully sent upstream the logs look like this:

    ##### 2019-06-27 17:36:56 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 1
# CRC_OK: 100.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 1 (24 bytes)
# PUSH_DATA datagrams sent: 2 (319 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (185 bytes)
# RF packets sent to concentrator: 1 (28 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:26, rej:0)
# TX rejected (collision beacon): 0.00% (req:26, rej:0)
# TX rejected (too late): 0.00% (req:26, rej:0)
# TX rejected (too early): 0.00% (req:26, rej:0)
# BEACON queued: 0
# BEACON sent so far: 0
# BEACON rejected: 0
### [JIT] ###
# SX1301 time (PPS): 284111900
src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
### [GPS] ###
# GPS sync is disabled
##### END #####

  2. When I do not get an upstream message I see one of the following:

    ### [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 (113 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (185 bytes)
# RF packets sent to concentrator: 1 (28 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:20, rej:0)
# TX rejected (collision beacon): 0.00% (req:20, rej:0)
# TX rejected (too late): 0.00% (req:20, rej:0)
# TX rejected (too early): 0.00% (req:20, rej:0)
# BEACON queued: 0
# BEACON sent so far: 0
# BEACON rejected: 0
### [JIT] ###
# SX1301 time (PPS): 4099071842
src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
### [GPS] ###
# GPS sync is disabled
##### END #####

    or

    ##### 2019-06-27 17:31:26 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 2
# CRC_OK: 50.00%, CRC_FAIL: 50.00%, NO_CRC: 0.00%
# RF packets forwarded: 1 (28 bytes)
# PUSH_DATA datagrams sent: 2 (328 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (185 bytes)
# RF packets sent to concentrator: 1 (28 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:21, rej:0)
# TX rejected (collision beacon): 0.00% (req:21, rej:0)
# TX rejected (too late): 0.00% (req:21, rej:0)
# TX rejected (too early): 0.00% (req:21, rej:0)
# BEACON queued: 0
# BEACON sent so far: 0
# BEACON rejected: 0
### [JIT] ###
# SX1301 time (PPS): 4279074379
src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
### [GPS] ###
# GPS sync is disabled
##### END #####

    or

    ##### 2019-06-27 17:38:26 GMT #####
### [UPSTREAM] ###
# RF packets received by concentrator: 0
# CRC_OK: 0.00%, CRC_FAIL: 0.00%, NO_CRC: 0.00%
# RF packets forwarded: 0 (0 bytes)
# PUSH_DATA datagrams sent: 1 (113 bytes)
# PUSH_DATA acknowledged: 100.00%
### [DOWNSTREAM] ###
# PULL_DATA sent: 3 (100.00% acknowledged)
# PULL_RESP(onse) datagrams received: 1 (185 bytes)
# RF packets sent to concentrator: 1 (28 bytes)
# TX errors: 0
# TX rejected (collision packet): 0.00% (req:27, rej:0)
# TX rejected (collision beacon): 0.00% (req:27, rej:0)
# TX rejected (too late): 0.00% (req:27, rej:0)
# TX rejected (too early): 0.00% (req:27, rej:0)
# BEACON queued: 0
# BEACON sent so far: 0
# BEACON rejected: 0
### [JIT] ###
# SX1301 time (PPS): 404113897
src/jitqueue.c:448:jit_print_queue(): INFO: [jit] queue is empty
### [GPS] ###
# GPS sync is disabled
##### END #####

Does this point to a configuration issue with the packet forwarder or perhaps a frequency mismatch between the class devices and the gateway? I'm not sure how to interpret the logs.

ronniesa commented 5 years ago

It seems a problem between the device and the gateway. You can see that there are CRC_FAIL and you can see here some possible causes: https://www.thethingsnetwork.org/docs/gateways/troubleshooting/semtech-udp.html#uplink-issues It could be a mismatch of settings between the concentrator and the device or you could try to move the gateway and the device further apart or in another location to see if it helps.

If you did not change it here is the us configuration that we use for the pktwrd for US freq: https://github.com/Azure/iotedge-lorawan-starterkit/blob/master/LoRaEngine/modules/LoRaWanPktFwdModule/global_conf.us.json you can double check with your device frequencies/channels.

gerfen commented 5 years ago

I think I'm finally getting somewhere... I can configure the frequency channel indexes for the class C device: image

By default the device is configured to support channels 0 - 71. I've had much better luck if I configure the device to only use channels 0 - 7. Referencing the image above could you give me guidance on which channels I should use?

gerfen commented 5 years ago

I'm closing this as setting the device to only use 8 channels has solved my issue with these particular Class C devices.

Thanks again for the assistance!