search

Azure / iot-edge-v1

Azure IoT Edge
http://azure.github.io/iot-edge/
Other
525 stars 258 forks source link

V2 - Raspberry Pi 3B IoT Edge Device doesn't respond on a desired properties update #598

Open HenrikBach1 opened 6 years ago

HenrikBach1 commented 6 years ago

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

varunpuranik commented 6 years ago

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.

HenrikBach1 commented 6 years ago

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

henriksen commented 6 years ago

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

dariuszparys commented 6 years ago

Thanks for the logs I'll have a look later today. /cc @varunpuranik

henriksen commented 6 years ago

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...

henriksen commented 6 years ago

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!

dariuszparys commented 6 years ago

@HenrikBach1 can you please submit your logs of edgeHub, edgeAgent and the Temperature Sensor you're using?

HenrikBach1 commented 6 years ago

Hi @dariuszparys,

All referenced files can found here.

Thank you.

/Henrik

dariuszparys commented 6 years ago

@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.

HenrikBach1 commented 6 years ago

@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.

HenrikBach1 commented 6 years ago

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.

HenrikBach1 commented 6 years ago

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.

dariuszparys commented 6 years ago

@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

HenrikBach1 commented 6 years ago

@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.

HenrikBach1 commented 6 years ago

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.

dariuszparys commented 6 years ago

@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

HenrikBach1 commented 6 years ago

Hi @varunpuranik and @dariuszparys ,

Note, that I forgot in my first try to include my login credentials to my above repo.

/Henrik

koncq commented 5 years ago

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

varunpuranik commented 5 years ago

@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?

koncq commented 5 years ago

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(PooledByteBuffer1 buf, Int32 reqCapacity, Int32 normCapacity) at DotNetty.Buffers.PoolArena1.Allocate(PoolThreadCache1 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

varunpuranik commented 5 years ago

@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