search

Azure / azure-iot-sdk-node

A Node.js SDK for connecting devices to Microsoft Azure IoT services
https://docs.microsoft.com/en-us/azure/iot-hub/
Other
261 stars 227 forks source link

Module deployed at iotedge device does not receive Module Identity Twin changes #509

Closed LMtx closed 5 years ago

LMtx commented 5 years ago

Context

Description of the issue:

Module deployed at iotedge does not receive module twin changes using twin.on('properties.desired', function(delta){...});. It looks like that function was executed only once when module started and was not listening for twins changes after that.

Code sample exhibiting the issue:

https://github.com/Azure/azure-iot-sdk-node/blob/fd2da51a7b5818ffbfb3f74dae0fed13bb7a34fb/device/samples/simple_sample_module_twin.js

Console log of the issue:

got client
client opened
twin created
twin contents:
{ reported: { update: [Function: update], '$version': 1 },
  desired: { text: 'abc', '$version': 21 } }
new desired properties received:
{"text":"abc","$version":21}
twin state reported

No further logs appeared even if I changed Module Identity Twin via Azure portal.

LMtx commented 5 years ago

I have the same issue when using C# in iotedge module. Updating Device Twins works perfectly well - the problem occurs only with edge device and module twin.

LMtx commented 5 years ago

The same code works in IoT Edge Solution in Simulator without any issues (but not on my RPi device).

LMtx commented 5 years ago

I checked the tcpdump and it does not seem to be a network issue.

What is interesting is that '$version' and attributes displayed by iotedge module during start are different than '$version' and attributes of module twins that I see via Azure portal. It looks like the module on edge device is watching different module twins than it should according to Azure portal.

LMtx commented 5 years ago

tcpdump with communication when I changed the module twin via portal:

tcpdump -XX -s0 -i wlan0 tcp and host not 192.168.0.11

12:16:01.902316 IP 192.168.0.15.58032 > 51.144.118.31.https: Flags [P.], seq 1782:1851, ack 6429, win 364, options [nop,nop,TS val 384076559 ecr 3469167990],
 length 69
        0x0000:  1498 7d81 8d97 b827 ebff e1cc 0800 4500  ..}....'......E.
        0x0010:  0079 ea84 4000 4006 e593 c0a8 000f 3390  .y..@.@.......3.
        0x0020:  761f e2b0 01bb 31b8 9e46 be67 0ec4 8018  v.....1..F.g....
        0x0030:  016c df5b 0000 0101 080a 16e4 8b0f cec7  .l.[............
        0x0040:  4d76 1503 0300 4083 ee10 c699 9be1 0b94  Mv....@.........
        0x0050:  f2bf 3e33 ed7f 7cf8 407f 2004 c743 cf14  ..>3..|.@....C..
        0x0060:  bc6a cb48 fac5 0894 fe61 2d8e 93d3 f47d  .j.H.....a-....}
        0x0070:  2176 a022 bf77 f29b a1ff ad3b 9919 95ed  !v.".w.....;....
        0x0080:  edda 797c 76f5 95                        ..y|v..
12:16:01.902568 IP 192.168.0.15.58032 > 51.144.118.31.https: Flags [F.], seq 1851, ack 6429, win 364, options [nop,nop,TS val 384076559 ecr 3469167990], leng
th 0
        0x0000:  1498 7d81 8d97 b827 ebff e1cc 0800 4500  ..}....'......E.
        0x0010:  0034 ea85 4000 4006 e5d7 c0a8 000f 3390  .4..@.@.......3.
        0x0020:  761f e2b0 01bb 31b8 9e8b be67 0ec4 8011  v.....1....g....
        0x0030:  016c cadc 0000 0101 080a 16e4 8b0f cec7  .l..............
        0x0040:  4d76                                     Mv
12:16:01.952593 IP 51.144.118.31.https > 192.168.0.15.58032: Flags [.], ack 1782, win 1024, options [nop,nop,TS val 3469275767 ecr 383968898], length 0
        0x0000:  b827 ebff e1cc 1498 7d81 8d97 0800 4528  .'......}.....E(
        0x0010:  0034 7e22 4000 6a06 2813 3390 761f c0a8  .4~"@.j.(.3.v...
        0x0020:  000f 01bb e2b0 be67 0ec4 31b8 9e46 8010  .......g..1..F..
        0x0030:  0400 c81a 0000 0101 080a cec8 f277 16e2  .............w..
        0x0040:  e682                                     ..
12:16:01.959555 IP 51.144.118.31.https > 192.168.0.15.58032: Flags [F.], seq 6429, ack 1852, win 1024, options [nop,nop,TS val 3469275773 ecr 384076559], len
gth 0
        0x0000:  b827 ebff e1cc 1498 7d81 8d97 0800 4528  .'......}.....E(
        0x0010:  0034 7e23 4000 6a06 2812 3390 761f c0a8  .4~#@.j.(.3.v...
        0x0020:  000f 01bb e2b0 be67 0ec4 31b8 9e8c 8011  .......g..1.....
        0x0030:  0400 233f 0000 0101 080a cec8 f27d 16e4  ..#?.........}..
        0x0040:  8b0f                                     ..
12:16:01.959662 IP 192.168.0.15.58032 > 51.144.118.31.https: Flags [.], ack 6430, win 364, options [nop,nop,TS val 384076616 ecr 3469275773], length 0
        0x0000:  1498 7d81 8d97 b827 ebff e1cc 0800 4500  ..}....'......E.
        0x0010:  0034 ea86 4000 4006 e5d6 c0a8 000f 3390  .4..@.@.......3.
        0x0020:  761f e2b0 01bb 31b8 9e8c be67 0ec5 8010  v.....1....g....
        0x0030:  016c 259a 0000 0101 080a 16e4 8b48 cec8  .l%..........H..
        0x0040:  f27d                                     .}

logs from edgeAgent:

2019-03-14 12:14:14.213 +00:00 [INF] - Executing command: "Update module NodeModule2"
2019-03-14 12:15:02.924 +00:00 [INF] - Executing command: "Start module NodeModule2"
2019-03-14 12:15:05.631 +00:00 [INF] - Plan execution ended for deployment 4
2019-03-14 12:15:05.836 +00:00 [INF] - Updated reported properties
2019-03-14 12:15:11.098 +00:00 [INF] - Updated reported properties

logs from edgeHub:

2019-03-14 12:15:11.256 +00:00 [INF] - Client lm_iotedge_dev_02/NodeModule2 in device scope authenticated locally.
2019-03-14 12:15:11.256 +00:00 [INF] - Successfully generated identity for clientId lm_iotedge_dev_02/NodeModule2 and username lingaro-iothub-dev.azure-devices.net/lm_iotedge_dev_02/NodeModule2/?api-version=2018-06-30&DeviceClientType=azure-iot-device%2F1.9.4%20(node%20v8.15.1%3B%20Debian%209.8%3B%20arm)
2019-03-14 12:15:11.257 +00:00 [INF] - ClientAuthenticated, lm_iotedge_dev_02/NodeModule2, 59301b71
2019-03-14 12:15:11.314 +00:00 [INF] - New device connection fordevice lm_iotedge_dev_02/NodeModule2
2019-03-14 12:15:11.319 +00:00 [INF] - Bind device proxy for device lm_iotedge_dev_02/NodeModule2
2019-03-14 12:15:11.320 +00:00 [INF] - Binding message channel for device Id lm_iotedge_dev_02/NodeModule2
2019-03-14 12:15:11.372 +00:00 [INF] - Processing subscription TwinResponse for client lm_iotedge_dev_02/NodeModule2.
2019-03-14 12:15:11.372 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client lm_iotedge_dev_02/NodeModule2.
2019-03-14 12:15:11.375 +00:00 [INF] - Set subscriptions from session state for lm_iotedge_dev_02/NodeModule2
2019-03-14 12:15:11.489 +00:00 [INF] - Processing subscription TwinResponse for client lm_iotedge_dev_02/NodeModule2.
2019-03-14 12:15:11.490 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client lm_iotedge_dev_02/NodeModule2.
2019-03-14 12:15:11.496 +00:00 [INF] - Set subscriptions from session state for lm_iotedge_dev_02/NodeModule2

Any help/ideas are very welcome!

anthonyvercolano commented 5 years ago

Thank you for all this information. I will be sitting down with the edge team tomorrow morning. I will update you after that with what we are doing.

enesuysal commented 5 years ago

Hi Łukasz,

I tried and reproduced your issue locally and you can find below resolution for that issue for your Raspberry pi.

https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot#stability-issues-on-resource-constrained-devices

Resolution For the IoT Edge hub, set an environment variable OptimizeForPerformance to false.

In the UI:

In the portal, navigate to Device Details > Set Modules > Configure advanced Edge Runtime settings. Create an environment variable for the Edge Hub module called OptimizeForPerformance that is set to false.

varunpuranik commented 5 years ago

@LMtx - Can you please confirm that your issue repros only on RPi? And can you please provide the entire edgeHub logs for the repro scenario? Does setting the OptimizeForPerformance=false, as @enesuysal suggested, resolve the issue? If so, then note that it is a required setting for RPi devices.

anthonyvercolano commented 5 years ago

@LMtx -

Looks like Varun will be looking closely at your issue. I will be closely monitoring this to see how it all turns or whether I need to take further action in the node SDK.

LMtx commented 5 years ago

@varunpuranik @enesuysal

When I set OptimizeForPerformance to false I got following error from my module:

lm@raspberrypi:~ $ iotedge logs -f NodeModule03

/app/app.js:18
        throw err;
        ^
NotConnectedError: socket hang up
    at Object.translateError (/app/node_modules/azure-iot-mqtt-base/lib/mqtt_translate_error.js:48:15)
    at constructor._onEnter (/app/node_modules/azure-iot-device-mqtt/lib/mqtt.js:92:76)
    at constructor.transition (/app/node_modules/machina/lib/machina.js:653:28)
    at constructor.Fsm.(anonymous function) [as transition] (/app/node_modules/machina/lib/machina.js:466:63)
    at /app/node_modules/azure-iot-device-mqtt/lib/mqtt.js:228:56
    at constructor._onEnter (/app/node_modules/azure-iot-mqtt-base/lib/mqtt_base.js:41:29)
    at constructor.transition (/app/node_modules/machina/lib/machina.js:653:28)
    at constructor.Fsm.(anonymous function) [as transition] (/app/node_modules/machina/lib/machina.js:466:63)
    at /app/node_modules/azure-iot-mqtt-base/lib/mqtt_base.js:67:44
    at MqttClient.<anonymous> (/app/node_modules/azure-iot-mqtt-base/lib/mqtt_base.js:238:17)

And it looks like PRi has some issues with iotedge connectivity:

root@raspberrypi:/home/lm# systemctl status iotedge
● iotedge.service - Azure IoT Edge daemon
   Loaded: loaded (/lib/systemd/system/iotedge.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2019-03-18 09:01:45 GMT; 11min ago
     Docs: man:iotedged(8)
 Main PID: 3182 (iotedged)
      CPU: 4.439s
   CGroup: /system.slice/iotedge.service
           └─3182 /usr/bin/iotedged -c /etc/iotedge/config.yaml

Mar 18 09:12:29 raspberrypi iotedged[3182]: 2019-03-18T09:12:29Z [INFO] - [mgmt] - - - [2019-03-18 09:12:29.180778769 UTC] "GET /modules?api-version=
Mar 18 09:12:34 raspberrypi iotedged[3182]: 2019-03-18T09:12:34Z [INFO] - [mgmt] - - - [2019-03-18 09:12:34.240982444 UTC] "GET /modules?api-version=
Mar 18 09:12:39 raspberrypi iotedged[3182]: 2019-03-18T09:12:39Z [INFO] - [mgmt] - - - [2019-03-18 09:12:39.316268697 UTC] "GET /modules?api-version=
Mar 18 09:12:44 raspberrypi iotedged[3182]: 2019-03-18T09:12:44Z [INFO] - [mgmt] - - - [2019-03-18 09:12:44.378393624 UTC] "GET /modules?api-version=
Mar 18 09:12:45 raspberrypi iotedged[3182]: 2019-03-18T09:12:45Z [INFO] - Checking edge runtime status
Mar 18 09:12:45 raspberrypi iotedged[3182]: 2019-03-18T09:12:45Z [INFO] - Edge runtime is running.
Mar 18 09:12:49 raspberrypi iotedged[3182]: 2019-03-18T09:12:49Z [INFO] - [mgmt] - - - [2019-03-18 09:12:49.446400056 UTC] "GET /modules?api-version=
Mar 18 09:12:51 raspberrypi iotedged[3182]: 2019-03-18T09:12:51Z [ERR!] - server connection error: (unknown)
Mar 18 09:12:51 raspberrypi iotedged[3182]: 2019-03-18T09:12:51Z [ERR!] - error writing a body to connection: Broken pipe (os error 32)
Mar 18 09:12:54 raspberrypi iotedged[3182]: 2019-03-18T09:12:54Z [INFO] - [mgmt] - - - [2019-03-18 09:12:54.512292233 UTC] "GET /modules?api-version=
LMtx commented 5 years ago

iotedge service restart did not help, but when I restarted the RPi device service started:

lm@raspberrypi:~ $ sudo -s
[sudo] password for lm:
root@raspberrypi:/home/lm# systemctl status iotedge
● iotedge.service - Azure IoT Edge daemon
   Loaded: loaded (/lib/systemd/system/iotedge.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2019-03-18 09:20:37 GMT; 2min 47s ago
     Docs: man:iotedged(8)
 Main PID: 1354 (iotedged)
      CPU: 3.450s
   CGroup: /system.slice/iotedge.service
           └─1354 /usr/bin/iotedged -c /etc/iotedge/config.yaml

Mar 18 09:22:38 raspberrypi iotedged[1354]: 2019-03-18T09:22:38Z [INFO] - Edge runtime is running.
Mar 18 09:22:42 raspberrypi iotedged[1354]: 2019-03-18T09:22:42Z [INFO] - [mgmt] - - - [2019-03-18 09:22:42.824309317 UTC] "GET /modules?api-version=
Mar 18 09:22:47 raspberrypi iotedged[1354]: 2019-03-18T09:22:47Z [INFO] - [mgmt] - - - [2019-03-18 09:22:47.891538030 UTC] "GET /modules?api-version=
Mar 18 09:22:52 raspberrypi iotedged[1354]: 2019-03-18T09:22:52Z [INFO] - [mgmt] - - - [2019-03-18 09:22:52.959295505 UTC] "GET /modules?api-version=
Mar 18 09:22:58 raspberrypi iotedged[1354]: 2019-03-18T09:22:58Z [INFO] - [mgmt] - - - [2019-03-18 09:22:58.021954363 UTC] "GET /modules?api-version=
Mar 18 09:23:03 raspberrypi iotedged[1354]: 2019-03-18T09:23:03Z [INFO] - [mgmt] - - - [2019-03-18 09:23:03.094988712 UTC] "GET /modules?api-version=
Mar 18 09:23:08 raspberrypi iotedged[1354]: 2019-03-18T09:23:08Z [INFO] - [mgmt] - - - [2019-03-18 09:23:08.145865171 UTC] "GET /modules?api-version=
Mar 18 09:23:13 raspberrypi iotedged[1354]: 2019-03-18T09:23:13Z [INFO] - [mgmt] - - - [2019-03-18 09:23:13.191170904 UTC] "GET /modules?api-version=
Mar 18 09:23:18 raspberrypi iotedged[1354]: 2019-03-18T09:23:18Z [INFO] - [mgmt] - - - [2019-03-18 09:23:18.255309742 UTC] "GET /modules?api-version=
Mar 18 09:23:23 raspberrypi iotedged[1354]: 2019-03-18T09:23:23Z [INFO] - [mgmt] - - - [2019-03-18 09:23:23.319555645 UTC] "GET /modules?api-version=

But my module has the same issue as above.

LMtx commented 5 years ago

@anthonyvercolano I created a new iot edge device in iot hub and that solved my connection issues. Changing the OptimizeForPerformance flag to false did not help - RPi is not receiving changes on module twin I do from portal. Same as before - module run in device simulator works perfectly well. I have Raspberry Pi 3 Model B.

LMtx commented 5 years ago

The same code worked after reinstallation linux on RPi from scratch. It is strange that no errors were reported by device.

Thank you for your investigation.

az-iot-builder-01 commented 5 years ago

@LMtx, @enesuysal, @varunpuranik, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey