iot-edge-v1
iot-edge-v1 copied to clipboard
V2 - Raspberry Pi 3B IoT Edge Device doesn't respond on a desired properties update
Hi @dariuszparys or @varunpuranik,
I have issues with receiving desired properties updates from Azure IoT Hub to my Raspberry Pi 3B running Rasbian Stretch.
I have checked that the issue exists both in the image from microsoft/azureiotedge-simulated-temperature-sensor:1.0-preview
and a build from the latest source code from https://github.com/Azure/iot-edge/tree/master/v2/samples/azureiotedge-simulated-temperature-sensor
to my repo hebhddauazureiotedgetest1.azurecr.io/azureiotedge-simulated-temperature-sensor-linux-arm:0.2
:
"properties": {
"desired": {
"SendData": true,
"SendInterval": 65,
"$metadata": {
"$lastUpdated": "2018-05-09T09:23:36.2694807Z",
"$lastUpdatedVersion": 2,
"SendData": {
"$lastUpdated": "2018-05-09T09:23:36.2694807Z",
"$lastUpdatedVersion": 2
},
"SendInterval": {
"$lastUpdated": "2018-05-09T09:23:36.2694807Z",
"$lastUpdatedVersion": 2
}
},
"$version": 2
},
Moreover, the above issue doesn't exists at your "reference" platform (Docker-on-Windows using the linux-x64 cpu architecture). So, in that respect, it seems to be a specific Raspbian (linux-arm
) issue.
OS: Raspbian GNU/Linux 9 (stretch)
@ Raspberry Pi 3B
Docker: Docker version 18.04.0-ce, build 3d479c0
IoT Edge Ctl: iotedgectl 1.0.0rc22
$ docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
5b4c5fdebbc6 hebhddauazureiotedgetest1.azurecr.io/azureiotedge-simulated-temperature-sensor-linux-arm:0.2 "dotnet azureiotedge…" About an hour ago Up About an hour tempSensor-2
b9fd9e0686e8 microsoft/azureiotedge-hub:1.0-preview "scripts/linux/start…" 3 hours ago Up 3 hours 0.0.0.0:443->443/tcp, 0.0.0.0:8883->8883/tcp edgeHub
c29b17426350 microsoft/azureiotedge-agent:1.0-preview "/usr/bin/dotnet Mic…" 3 hours ago Up 3 hours edgeAgent
To read from my repo, use: hebhddauazureiotedgetest1
/wNf79YKKRZtEP9jVAIcbWRDu12/jwrNG
Thank you.
/Henrik
Hi Henrik,
Can you provide some more details on what kind of problems you are running into? Are you not getting the Desired properties updated callback at all? Or is there some other problem? Also, if you run your code (the same module code) on your dev box, does it work?
The reason I ask is because desired property update callbacks are that way not platform specific, so I am trying to understand your scenario and why you might be seeing this.
Hi @varunpuranik or @dariuszparys ,
I don't get the desired properties updated callback on Raspbian, but only on (Docker-on-)Windows. So, in that sense it works only on one platform and in that sense the Windows box has become my dev box, at the moment.
Moreover, I have also observed, that the updated desired properties eventually reaches the Edge, but it is not pickup up by the desired properties updated callback run-time. This is observed when I delete and re-add the module (given the same module name).
I would like to provide you with more details. However, I don't exactly know, where to look in this case. Can you suggest which logs I should provide you?
Thank you.
/Henrik
I'm having the same problem, but both on a RPi 2 and on my Windows 10 PC. I've tried running my own code and I've tried running the tempSensor sample module.
Desired properties are picked up if I do an explicit read
var moduleTwin = await ioTHubModuleClient.GetTwinAsync ();
var moduleTwinCollection = moduleTwin.Properties.Desired;
but any callbacks registered are never called.
await ioTHubModuleClient.SetDesiredPropertyUpdateCallbackAsync (OnDesiredPropertiesUpdate, null);
Similarly, a registered method handler is also never called.
await ioTHubModuleClient.SetMethodHandlerAsync ("setState", SetStateMethod, null);
Trying to invoke the direct method just gives me a timeout message:
{"message":"Device {\"Message\":\"{\\\"errorCode\\\":404103,\\\"trackingId\\\":\\\"632f10b976a44866a3d177c28b715f53-G:11-TimeStamp:05/16/2018 13:18:33\\\",\\\"message\\\":\\\"Timed out waiting for device to connect.\\\",\\\"info\\\":{\\\"timeout\\\":\\\"00:00:10\\\"},\\\"timestampUtc\\\":\\\"2018-05-16T13:18:33.894092Z\\\"}\",\"ExceptionMessage\":\"\"} not registered"}
Windows 10
> [System.Environment]::OSVersion.Version
Major Minor Build Revision
----- ----- ----- --------
6 2 9200 0
> iotedgectl.exe --version
iotedgectl 1.0.0rc22
> docker --version
Docker version 18.05.0-ce-rc1, build 33f00ce
> docker ps -a --format "table {{.ID}}\t{{.Names}}\t{{.Image}}"
CONTAINER ID NAMES IMAGE
fb0160795699 edgeHub microsoft/azureiotedge-hub:1.0-preview
e76421cc4122 tempSensor microsoft/azureiotedge-simulated-temperature-sensor:1.0-preview
5db2e09676f2 edgeAgent microsoft/azureiotedge-agent:1.0-preview
Raspberry 2
pi@pidev:~ $ lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description: Raspbian GNU/Linux 9.4 (stretch)
Release: 9.4
Codename: stretch
pi@pidev:~ $ docker --version
Docker version 18.04.0-ce, build 3d479c0
pi@pidev:~ $ iotedgectl --version
iotedgectl 1.0.0rc22
pi@pidev:~ $ docker ps -a
CONTAINER ID IMAGE COMMAND NAMES
501d801428fe privateacr.azurecr.io/custommodule:0.1.9-arm32v7 "dotnet CustomModule.…" customModule
9ba60a2ee487 microsoft/azureiotedge-agent:1.0-preview "/usr/bin/dotnet Mic…" edgeAgent
d692e148cf6d microsoft/azureiotedge-hub:1.0-preview "scripts/linux/start…" edgeHub
Docker base images are microsoft/dotnet:2.0-runtime-stretch
and microsoft/dotnet:2.0-runtime-stretch-arm32v7
I've attached log files from the Windows machine with IoTEdgeCtrl log level debug. I see no sign in the logs when trying to update desired properties or invoking a direct method. edgeAgent.log.txt edgeHub.log.txt tempSensor.log.txt
Thanks for the logs I'll have a look later today. /cc @varunpuranik
Strangest thing, today desired properties updates just decided to work. Update desired updates in the Module Twin and boom, the update triggered on the PI. No change in the Direct Method though...
Well, turns out I've been doing the wrong thing. Doh! I expected the Direct Method button in the IoT Edge Device page to be able to work with modules, but it doesn't.
Also, I tried with the ServiceClient.InvokeDeviceMethodAsync
method but there was no way to specify the module there either. However, if I use the 1.16.0-preview-004
version of Microsoft.Azure.Devices
instead of the 1.6
version, there is a new parameter moduleId
. That worked.
var response = await serviceClient.InvokeDeviceMethodAsync ("myDevice", "myModule", methodInvocation);
works like a charm now. All good!
@HenrikBach1 can you please submit your logs of edgeHub, edgeAgent and the Temperature Sensor you're using?
Hi @dariuszparys,
All referenced files can found here.
- I upgraded my system (Raspberry Pi 3B/Raspbian 9 (Stretch) to the latest runtimes,
- I re-installed and setup your azure iot edge runtime, etc.,
- I deployed your tempSensor module (deployment.json-1),
- I updated the desired properties in the module (module-twin.json-1) at about 07:56,
- I've attached your requested logs (tempSensor.log-1, edgeAgent.log-1, and edgeHub.log-1).
Thank you.
/Henrik
@HenrikBach1 I just tried to repro the problem. I can't. I can successfully update the module twin properties to the temperature simulator running on my Raspberry PI 3B. The question I have is how do you update the properties? I ran into problems using the portal what I did then was to leverage the Azure CLI IoT Hub extensions to update them.
My command I used was
az iot hub module-twin update --module-id tempSensor --device-id thepi --hub-name codin --set properties.desired='{\"SendInterval\": 7}'
from Powershell. From Bash you need different JSON encoding.
@dariuszparys ,
I haven't not tried to do a twin-module update from the CLI, yet. I have only done that from the Portal.
If I now change the SendInterval to 30 from Portal, then, if I use your command excluding the --set
option:
$ az.cmd iot hub module-twin update --module-id tempSensor --device-id hebh-IoT-Edge-Rpi3B --hub-name hebh-IoT-Hub-Test
{
"authenticationType": "sas",
"cloudToDeviceMessageCount": 0,
"connectionState": "Connected",
"deviceEtag": "NDUyOTc5MDgw",
"deviceId": "hebh-IoT-Edge-Rpi3B",
"etag": "AAAAAAAAAAY=",
"lastActivityTime": "0001-01-01T00:00:00",
"moduleId": "tempSensor",
"properties": {
"desired": {
"$metadata": {
"$lastUpdated": "2018-06-06T07:50:36.6522808Z",
"$lastUpdatedVersion": 6,
"SendData": {
"$lastUpdated": "2018-06-06T07:50:36.6522808Z",
"$lastUpdatedVersion": 6
},
"SendInterval": {
"$lastUpdated": "2018-06-06T07:50:36.6522808Z",
"$lastUpdatedVersion": 6
}
},
"$version": 6,
"SendData": true,
"SendInterval": 30
},
"reported": {
"$metadata": {
"$lastUpdated": "0001-01-01T00:00:00Z"
},
"$version": 1
}
},
"status": "enabled",
"statusUpdateTime": "0001-01-01T00:00:00",
"version": 7,
"x509Thumbprint": {
"primaryThumbprint": null,
"secondaryThumbprint": null
}
}
But, the tempSensor module doesn't react on that, too...
If I issue:
$ az.cmd iot hub module-twin update --module-id tempSensor --device-id hebh-IoT-Edge-Rpi3B --hub-name hebh-IoT-Hub-Test --set properties.desired='{\"SendInterval\": 7}'
'C:\Program' is not recognized as an internal or external command,
operable program or batch file.
hebh@COP382 ~/projects/ddau-azure-iot-edge/logs
$ az.cmd --version
azure-cli (2.0.32)
Is there a way to see, which desired properties my pi has received?...
Thank you.
Hi @dariuszparys ,
If I move the sd-card to another pi2b, then the result is the same:
$ az.cmd iot hub module-twin update --module-id tempSensor --device-id hebh-IoT-Edge-Rpi3B --hub-name hebh-IoT-Hub-Test
{
"authenticationType": "sas",
"cloudToDeviceMessageCount": 0,
"connectionState": "Connected",
"deviceEtag": "NDUyOTc5MDgw",
"deviceId": "hebh-IoT-Edge-Rpi3B",
"etag": "AAAAAAAAAAc=",
"lastActivityTime": "0001-01-01T00:00:00",
"moduleId": "tempSensor",
"properties": {
"desired": {
"$metadata": {
"$lastUpdated": "2018-06-06T08:16:54.5749582Z",
"$lastUpdatedVersion": 7,
"SendData": {
"$lastUpdated": "2018-06-06T08:16:54.5749582Z",
"$lastUpdatedVersion": 7
},
"SendInterval": {
"$lastUpdated": "2018-06-06T08:16:54.5749582Z",
"$lastUpdatedVersion": 7
}
},
"$version": 7,
"SendData": true,
"SendInterval": 30
},
"reported": {
"$metadata": {
"$lastUpdated": "0001-01-01T00:00:00Z"
},
"$version": 1
}
},
"status": "enabled",
"statusUpdateTime": "0001-01-01T00:00:00",
"version": 8,
"x509Thumbprint": {
"primaryThumbprint": null,
"secondaryThumbprint": null
}
}
I have added a tempSensor.log-2 to here.
Hi @dariuszparys ,
PowerShell doesn't seem to work with azure-cli, even though, I've logged in to the portal:
PS C:\Users\hebh> az.cmd iot hub module-twin update --module-id tempSensor --device-id hebh-IoT-Edge-Rpi3B --hub-name he
bh-IoT-Hub-Test --set properties.desired='{\"SendInterval\": 7}'
az iot hub: 'module-twin' is not an az iot hub command. See 'az iot hub --help'.
PS C:\Users\hebh> az.cmd --version
azure-cli (2.0.32)
The Bash I'm using is:
$ bash --version
GNU bash, version 4.4.12(3)-release (x86_64-unknown-cygwin)
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software; you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
And, as far as I can remember, I've installed the azure-cli with chocolatey:
$ choco upgrade azure-cli -y
Chocolatey v0.10.11
Upgrading the following packages:
azure-cli
By upgrading you accept licenses for the packages.
azure-cli v2.0.32 is the latest version available based on your source(s).
Thank you.
@HenrikBach1 you have to install the iot hub extension prior to using it.
az extension add --name azure-cli-iot-ext
You can read the details here. https://docs.microsoft.com/en-us/azure/iot-dps/how-to-manage-dps-with-cli
Further the logs you specified are referencing the microsoft/azureiotedge-simulated-temperature-sensor:1.0-preview
container. This one doesn't implement the update properties behavior as described here https://github.com/Azure/iot-edge/blob/master/v2/samples/azureiotedge-simulated-temperature-sensor/README.md
@dariuszparys Ok, then I'll (try to) show that the update properties behavior doesn't do what is expected in the v2/samples tomorrow , because, it was that code I've made module tests from...
I thought that the microsoft/azureiotedge-simulated-temperature-sensor:1.0-preview
was made from that code, too.
Thank you.
Hi @dariuszparys ,
Today, I've updated and build a new version of the tempSensor module from https://github.com/Azure/iot-edge/tree/master/v2/samples/azureiotedge-simulated-temperature-sensor.
I updated the desired properties at 2018-06-07T12:01:59.5952151Z
with no effect to its internal values in the module. I waited to about 06/07/2018 12:10:10
before I stopped monitoring the module.
I've updated the logs as requested here.
You can reach my version of the module with these preliminary credentials: hebhddauazureiotedgetest1/wNf79YKKRZtEP9jVAIcbWRDu12/jwrNG
.
I'm doing my tests on a Rpi2B device.
Thank you.
@varunpuranik This time there is an exception in the CloudProxy code. Can you please check what could be the cause? Here are the log references for this exception
https://gist.github.com/HenrikBach1/ac27243275857fc8170deef4c13823f3#file-edgehub-log-L2410-L2417
/cc @HenrikBach1
Hi @varunpuranik and @dariuszparys ,
Note, that I forgot in my first try to include my login credentials to my above repo.
/Henrik
Hi, anyone resolved that issue? I am experiencing same problem, but with module twin, instead of device twin. Module is receiving notifications on desired properties changed on amd64, but on arm32v7 nothing happens, it can only update on startup...
Best regards, Bart
@koncewiczbartosz - What version of the EdgeHub are you using? The version information is at the top of the EdgeHub logs. We have had issues with the C# SDK that EdgeHub uses losing the twin link to IoTHub, causing it to lose desired property updates. But if you provide me the entire edgeHub logs for the repro scenario, I can take a look to see if I can spot anything. Also - from what we have seen in our testing, the behavior should not be different on arm32v7 vs amd64. Are you seeing this consistently on one and not the other? If so, do you have the repro steps?
Hi @varunpuranik first of all, I am using version 1.0.6.19913336 of EdgeHub.
It always behaves the same way, the module has started, uploaded twin at startup, then I change desired properties of module twin configuration in Azure Portal manually and nothing happens on Raspberry Pi. While in simulator and my laptop (Windows 10, linux container) it works perfectly fine - updates twins in blink of an eye.
For issue reproduction, restart module and change single property in twin collection.
NOTE: Error related to raspberry-device/adsPublisher is not relevant, issue is related to s7publisher. Here are the logs as requested:
`[2019-03-29 08:33:32 +00:00]: Starting Edge Hub [03/29/2019 08:33:33.460 AM] Edge Hub Main() [03/29/2019 08:33:39.020 AM] Found intermediate certificates: [CN=iotedged workload ca:06/16/2019 09:39:44],[CN=Test Edge Device CA:06/16/2019 09:39:44],[CN=Test Edge Owner CA:06/16/2019 09:39:44] 2019-03-29 08:33:48.075 +00:00 [INF] - Created persistent store at /tmp/edgeHub 2019-03-29 08:33:48.725 +00:00 [INF] - Starting Edge Hub 2019-03-29 08:33:48.727 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝
██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝
2019-03-29 08:33:48.737 +00:00 [INF] - Version - 1.0.6.19913336 (8288bc9bd6f6e15295fea506cd3f99d7f6347a6a)
2019-03-29 08:33:48.754 +00:00 [INF] - Loaded server certificate with expiration date of "2019-06-16T09:39:44.0000000+00:00"
2019-03-29 08:33:48.899 +00:00 [INF] - Created new message store
2019-03-29 08:33:48.899 +00:00 [INF] - Started task to cleanup processed and stale messages
2019-03-29 08:33:48.908 +00:00 [INF] - Created device scope identities cache
2019-03-29 08:33:48.961 +00:00 [INF] - Starting refresh of device scope identities cache
2019-03-29 08:33:49.631 +00:00 [INF] - Initialized twin manager v1.
2019-03-29 08:33:49.684 +00:00 [INF] - Initializing configuration
2019-03-29 08:33:49.825 +00:00 [INF] - New device connection for device raspberry-device/$edgeHub
2019-03-29 08:33:50.131 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberry-device/$edgeHub via AMQP...
2019-03-29 08:33:54.047 +00:00 [INF] - Exiting disconnected state
2019-03-29 08:33:54.063 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
2019-03-29 08:33:54.078 +00:00 [INF] - Processing subscriptions for client raspberry-device/$edgeHub.
2019-03-29 08:33:54.111 +00:00 [INF] - Cloud connection for raspberry-device/$edgeHub is True
2019-03-29 08:33:54.144 +00:00 [INF] - Connection status for raspberry-device/$edgeHub changed to ConnectionEstablished
2019-03-29 08:33:54.170 +00:00 [INF] - Entering connected state
2019-03-29 08:33:54.187 +00:00 [INF] - Created cloud proxy for client raspberry-device/$edgeHub via AMQP, with client operation timeout 20 seconds.
2019-03-29 08:33:54.221 +00:00 [INF] - Initialized cloud proxy 3f51447d-4e05-47ac-9714-754d6c3c06cf for raspberry-device/$edgeHub
2019-03-29 08:33:54.237 +00:00 [INF] - Created cloud connection for client raspberry-device/$edgeHub
2019-03-29 08:33:54.348 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/$edgeHub.
2019-03-29 08:33:54.430 +00:00 [INF] - Processing subscription Methods for client raspberry-device/$edgeHub.
2019-03-29 08:33:54.997 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/$edgeHub.
2019-03-29 08:33:55.013 +00:00 [INF] - Processing subscription Methods for client raspberry-device/$edgeHub.
2019-03-29 08:33:57.590 +00:00 [INF] - Obtained edge hub config from module twin
2019-03-29 08:33:58.540 +00:00 [INF] - Set the following 1 route(s) in edge hub
2019-03-29 08:33:58.547 +00:00 [INF] - route: FROM /messages/* INTO $upstream
2019-03-29 08:33:58.558 +00:00 [INF] - Updated message store TTL to 7200 seconds
2019-03-29 08:33:58.560 +00:00 [INF] - Updated the edge hub store and forward configuration
2019-03-29 08:33:58.563 +00:00 [INF] - Initialized edge hub configuration
2019-03-29 08:33:58.653 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
2019-03-29 08:33:59.166 +00:00 [INF] - Scheduling server certificate renewal for "2019-06-16T09:37:14.0006141Z".
2019-03-29 08:33:59.176 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
2019-03-29 08:33:59.203 +00:00 [INF] - Starting MQTT head
2019-03-29 08:33:59.664 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
2019-03-29 08:34:00.112 +00:00 [INF] - Starting AMQP head
2019-03-29 08:34:00.223 +00:00 [INF] - Started MQTT head
2019-03-29 08:34:00.723 +00:00 [INF] - Started AMQP head
2019-03-29 08:34:00.738 +00:00 [INF] - Starting HTTP head
2019-03-29 08:34:01.322 +00:00 [INF] - User profile is available. Using '"/home/edgehubuser/.aspnet/DataProtection-Keys"' as key repository; keys will not be encrypted at rest.
2019-03-29 08:34:03.445 +00:00 [INF] - Client raspberry-device/adsPublisher in device scope authenticated locally.
2019-03-29 08:34:03.458 +00:00 [INF] - Successfully generated identity for clientId raspberry-device/adsPublisher and username iothub-mpn-andea-dev.azure-devices.net/raspberry-device/adsPublisher/?api-version=2017-11-08-preview&DeviceClientType=iothubclient%2f1.2.12%20(native%3b%20Linux%3b%20armv7l)
2019-03-29 08:34:03.476 +00:00 [INF] - ClientAuthenticated, raspberry-device/adsPublisher, 0465f37d
2019-03-29 08:34:03.691 +00:00 [INF] - New device connection for device raspberry-device/adsPublisher
2019-03-29 08:34:03.712 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
2019-03-29 08:34:03.755 +00:00 [INF] - Bind device proxy for device raspberry-device/adsPublisher
2019-03-29 08:34:03.761 +00:00 [INF] - Binding message channel for device Id raspberry-device/adsPublisher
2019-03-29 08:34:03.852 +00:00 [INF] - Started HTTP head
2019-03-29 08:34:03.920 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberry-device/adsPublisher via AMQP...
2019-03-29 08:34:04.063 +00:00 [INF] - Cloud connection for raspberry-device/adsPublisher is True
2019-03-29 08:34:04.063 +00:00 [INF] - Connection status for raspberry-device/adsPublisher changed to ConnectionEstablished
2019-03-29 08:34:04.064 +00:00 [INF] - Created cloud proxy for client raspberry-device/adsPublisher via AMQP, with client operation timeout 20 seconds.
2019-03-29 08:34:04.065 +00:00 [INF] - Initialized cloud proxy b1e9b340-ecb2-4d72-a9c2-bb30ac3d8aeb for raspberry-device/adsPublisher
2019-03-29 08:34:04.065 +00:00 [INF] - Created cloud connection for client raspberry-device/adsPublisher
2019-03-29 08:34:04.066 +00:00 [INF] - Processing subscription ModuleMessages for client raspberry-device/adsPublisher.
2019-03-29 08:34:04.072 +00:00 [INF] - Processing subscription TwinResponse for client raspberry-device/adsPublisher.
2019-03-29 08:34:04.072 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/adsPublisher.
2019-03-29 08:34:04.279 +00:00 [INF] - Set subscriptions from session state for raspberry-device/adsPublisher
2019-03-29 08:34:04.562 +00:00 [WRN] - Error in connection established callback for client raspberry-device/adsPublisher
System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
at DotNetty.Buffers.HeapArena.NewChunk(Int32 pageSize, Int32 maxOrder, Int32 pageShifts, Int32 chunkSize)
at DotNetty.Buffers.PoolArena1.AllocateNormal(PooledByteBuffer
1 buf, Int32 reqCapacity, Int32 normCapacity)
at DotNetty.Buffers.PoolArena1.Allocate(PoolThreadCache
1 cache, PooledByteBuffer1 buf, Int32 reqCapacity) at DotNetty.Buffers.PooledByteBufferAllocator.NewHeapBuffer(Int32 initialCapacity, Int32 maxCapacity) at DotNetty.Buffers.AbstractByteBufferAllocator.Buffer(Int32 initialCapacity, Int32 maxCapacity) at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ByteBufferConverter.ToByteBuffer(Byte[] bytes) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ByteBufferConverter.cs:line 38 at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ProtocolGatewayMessageConverter.FromMessage(IMessage message) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ProtocolGatewayMessageConverter.cs:line 101 at Microsoft.Azure.Devices.Edge.Hub.Mqtt.DeviceProxy.OnDesiredPropertyUpdates(IMessage desiredProperties) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/DeviceProxy.cs:line 112 at Microsoft.Azure.Devices.Edge.Hub.Core.Device.DeviceMessageHandler.OnDesiredPropertyUpdates(IMessage twinUpdates) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/device/DeviceMessageHandler.cs:line 389 at Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager.SendDesiredPropertiesToDeviceProxy(String id, IMessage desired) at Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager.GetTwinInfoWhenCloudOnlineAsync(String id, ICloudProxy cp, Boolean sendDesiredPropertyUpdate) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/TwinManager.cs:line 202 at Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager.<>c__DisplayClass29_0.<<ProcessConnectionEstablishedForDevice>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/TwinManager.cs:line 327 --- End of stack trace from previous location where exception was thrown --- at Microsoft.Azure.Devices.Edge.Hub.Core.TwinManager.ProcessConnectionEstablishedForDevice(IIdentity identity) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/TwinManager.cs:line 323 2019-03-29 08:34:08.109 +00:00 [INF] - Processing subscription ModuleMessages for client raspberry-device/adsPublisher. 2019-03-29 08:34:08.109 +00:00 [INF] - Processing subscription TwinResponse for client raspberry-device/adsPublisher. 2019-03-29 08:34:08.110 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/adsPublisher. 2019-03-29 08:34:08.111 +00:00 [INF] - Set subscriptions from session state for raspberry-device/adsPublisher 2019-03-29 08:34:08.712 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 093cddd0 2019-03-29 08:34:19.185 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 1a4ef8d0 2019-03-29 08:34:29.524 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 752c51a2 2019-03-29 08:34:39.880 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 0ff49295 2019-03-29 08:34:50.267 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 1054b5b9 2019-03-29 08:35:00.647 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 1fd57e91 2019-03-29 08:35:10.998 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 70a6b16a 2019-03-29 08:35:21.917 +00:00 [INF] - Client raspberry-device/s7publisher in device scope authenticated locally. 2019-03-29 08:35:21.918 +00:00 [INF] - Successfully generated identity for clientId raspberry-device/s7publisher and username raspberrypi/raspberry-device/s7publisher/?api-version=2018-06-30&DeviceClientType=.NET%2F1.19.0%20%28.NET%20Core%204.6.27414.06%3B%20Linux%204.14.79-v7%2B%20%231159%20SMP%20Sun%20Nov%204%2017%3A50%3A20%20GMT%202018%3B%20Arm%29 2019-03-29 08:35:21.918 +00:00 [INF] - ClientAuthenticated, raspberry-device/s7publisher, 1cd02c4b 2019-03-29 08:35:21.975 +00:00 [INF] - New device connection for device raspberry-device/s7publisher 2019-03-29 08:35:21.976 +00:00 [INF] - Bind device proxy for device raspberry-device/s7publisher 2019-03-29 08:35:21.977 +00:00 [INF] - Binding message channel for device Id raspberry-device/s7publisher 2019-03-29 08:35:22.171 +00:00 [INF] - Attempting to connect to IoT Hub for client raspberry-device/s7publisher via AMQP... 2019-03-29 08:35:22.369 +00:00 [INF] - Cloud connection for raspberry-device/s7publisher is True 2019-03-29 08:35:22.370 +00:00 [INF] - Connection status for raspberry-device/s7publisher changed to ConnectionEstablished 2019-03-29 08:35:22.433 +00:00 [INF] - Created cloud proxy for client raspberry-device/s7publisher via AMQP, with client operation timeout 20 seconds. 2019-03-29 08:35:22.433 +00:00 [INF] - Initialized cloud proxy 8cf85865-5453-465f-9dfa-c60c69ff858c for raspberry-device/s7publisher 2019-03-29 08:35:22.434 +00:00 [INF] - Created cloud connection for client raspberry-device/s7publisher 2019-03-29 08:35:22.434 +00:00 [INF] - Processing subscription TwinResponse for client raspberry-device/s7publisher. 2019-03-29 08:35:22.435 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/s7publisher. 2019-03-29 08:35:22.521 +00:00 [INF] - Set subscriptions from session state for raspberry-device/s7publisher 2019-03-29 08:35:25.338 +00:00 [INF] - Processing subscription TwinResponse for client raspberry-device/s7publisher. 2019-03-29 08:35:25.338 +00:00 [INF] - Processing subscription DesiredPropertyUpdates for client raspberry-device/s7publisher. 2019-03-29 08:35:25.340 +00:00 [INF] - Set subscriptions from session state for raspberry-device/s7publisher 2019-03-29 08:38:58.713 +00:00 [INF] - Reauthenticating connected clients 2019-03-29 08:43:58.660 +00:00 [INF] - Reauthenticating connected clients
@koncewiczbartosz - thanks for all the details.
From the logs, looks like you are running into the OOM exception - System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown. at DotNetty.Buffers.HeapArena.NewChunk(Int32 pageSize, Int32 maxOrder, Int32 pageShifts, Int32 chunkSize)
Have you set the OptimizeForPerformance flag to false for the EdgeHub, as explained here? https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot#stability-issues-on-resource-constrained-devices