iotedge: Simple custom module stops sending mqtt msgs and cannot recover

Expected Behavior

Slim custom module should run alongside edgeAgent and edgeHub while sending mqtt msgs to iothub on a small device.

Current Behavior

Custom module fails after some time, and cannot restart.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. Setup edgeAgent with the following environment variables:
{
    "RocksDB_MaxTotalWalSize": 4194304,
    "SendRuntimeQualityTelemetry": false
}

And the following create options:

{
    "HostConfig": {
        "Dns": [
            "1.1.1.1"
        ],
        "Memory": 209715200
    }
}
  1. Setup edgeHub with the following environment variables:
{
    "OptimizeForPerformance": false,
    "amqpSettings__enabled": false,
    "mqttSettings__enabled": true,
    "httpSettings__enabled": false,
    "UpstreamProtocol": Mqtt,
    "RocksDB_MaxTotalWalSize": 4194304
}

And the following create options:

{
    "HostConfig": {
        "Dns": [
            "1.1.1.1"
        ],
        "PortBindings": {
            "443/tcp": [
                {
                    "HostPort": "443"
                }
            ],
            "5671/tcp": [
                {
                    "HostPort": "5671"
                }
            ],
            "8883/tcp": [
                {
                    "HostPort": "8883"
                }
            ]
        },
        "Memory": 131072000
    }
}
  1. Create custom python module (SimpleStupidModule) with the following logic:
from azure.iot.device.aio import IoTHubModuleClient
from azure.iot.device import Message

    print("SIMPLESTUPIDMODULE - Module init")
    module_client = IoTHubModuleClient.create_from_edge_environment()
    await module_client.connect()
    
    while True:
        print("start " + str(datetime.utcnow()))
        if not module_client.connected:
            print("SIMPLESTUPIDMODULE - Module client creating")
            module_client = IoTHubModuleClient.create_from_edge_environment()
            print("SIMPLESTUPIDMODULE - Module client created")
            await module_client.connect()
            i = 0
            print("SIMPLESTUPIDMODULE - Module client connected")
            while not module_client.connected:
                i += 1
                time.sleep(1)
                if i > 300: #5 minutes has passed
                    raise Exception("<< Unable to connect... >>")

        #make msg
        msg = Message('"im alive"')

        print("SIMPLESTUPIDMODULE - before send")
        await module_client.send_message_to_output(msg, "IoTHub")
        print("SIMPLESTUPIDMODULE - after send")
        time.sleep(60)

Context (Environment)

Output of iotedge check

This was run at a time where i was not receiving msgs in the iothub from the device.

Click here 

~ # iotedge check
Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ config.yaml has correct hostname - OK
× config.yaml has correct URIs for daemon mgmt endpoint - Error
    Unable to find image 'mcr.microsoft.com/azureiotedge-diagnostics:1.1.0' locally
    docker: Error response from daemon: Get "https://mcr.microsoft.com/v2/": net/http: TLS handshake timeout.
    See 'docker run --help'.
‼ latest security daemon - Warning
    Installed IoT Edge daemon has version 1.1.0 but 1.1.9 is the latest stable version available.
    Please see https://aka.ms/iotedge-update-runtime for update instructions.
‼ host time is close to real time - Warning
    Time on the device is out of sync with the NTP server. This may cause problems connecting to IoT Hub.
    Please ensure time on device is accurate, for example by installing an NTP daemon.
× container time is close to host time - Error
    Could not query local time inside container
√ DNS server - OK
√ production readiness: identity certificates expiry - OK
√ production readiness: certificates - OK
‼ production readiness: container engine - Warning
    Device is not using a production-supported container engine (moby-engine).
    Please see https://aka.ms/iotedge-prod-checklist-moby for details.
√ production readiness: logs policy - OK
‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
    The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.
    Data might be lost if the module is deleted or updated.
    Please see https://aka.ms/iotedge-storage-host for best practices.
‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning
    The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem.
    Data might be lost if the module is deleted or updated.
    Please see https://aka.ms/iotedge-storage-host for best practices.

Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with DPS endpoint - OK
√ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
√ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
× container on the default network can connect to IoT Hub AMQP port - Error
    Container on the default network could not connect to ccj-dev-iothub.azure-devices.net:5671
× container on the default network can connect to IoT Hub HTTPS / WebSockets port - Error
    Container on the default network could not connect to ccj-dev-iothub.azure-devices.net:443
× container on the default network can connect to IoT Hub MQTT port - Error
    Container on the default network could not connect to ccj-dev-iothub.azure-devices.net:8883
× container on the IoT Edge module network can connect to IoT Hub AMQP port - Error
    Container on the azure-iot-edge network could not connect to ccj-dev-iothub.azure-devices.net:5671
× container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - Error
    Container on the azure-iot-edge network could not connect to ccj-dev-iothub.azure-devices.net:443
× container on the IoT Edge module network can connect to IoT Hub MQTT port - Error
    Container on the azure-iot-edge network could not connect to ccj-dev-iothub.azure-devices.net:8883

12 check(s) succeeded.
5 check(s) raised warnings. Re-run with --verbose for more details.
8 check(s) raised errors. Re-run with --verbose for more details.

Device Information

  • Host OS [e.g. Ubuntu 18.04, Windows Server IoT 2019]: Buildroot 2020.11.2
  • Architecture [e.g. amd64, arm32, arm64]: arm32
  • Container OS [e.g. Linux containers, Windows containers]: Linux

Runtime Versions

  • aziot-edged [run iotedge version]: iotedge 1.1.0
  • Edge Agent [image tag (e.g. 1.0.0)]: 1.1
  • Edge Hub [image tag (e.g. 1.0.0)]: 1.1
  • Docker/Moby [run docker version]:
Output of docker version 

Client:
 Version:           19.03.13
 API version:       1.40
 Go version:        go1.15.6
 Git commit:        19.03.13
 Built:             unknown-buildtime
 OS/Arch:           linux/arm
 Experimental:      false

Server:
 Engine:
  Version:          19.03.13
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.15.6
  Git commit:
  Built:            Sat Mar  6 22:42:04 CET 2021
  OS/Arch:          linux/arm
  Experimental:     false
 containerd:
  Version:          1.4.3
  GitCommit:
 runc:
  Version:          1.0.0-rc92
  GitCommit:

Logs

Note: i have replaced some infomation with scope_id, registration_id and hubname.

aziot-edged logs 

<6>2022-02-15T08:18:21+0000 Waiting for docker to start...
<6>2022-02-15T08:19:31+0000 docker is running, starting iotedged
<6>2022-02-15T08:19:32Z [INFO] - Starting Azure IoT Edge Security Daemon
<6>2022-02-15T08:19:32Z [INFO] - Version - 1.1.0
<6>2022-02-15T08:19:32Z [INFO] - Using config file: /persistent/etc/iotedge/config.yaml
...
...
<6>2022-02-17T04:18:51Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:20:46Z [INFO] - Querying system resources...
<6>2022-02-17T04:22:25Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:22:28Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:25:17Z [INFO] - [work] - - - [2022-02-17 04:25:14.984572670 UTC] "POST /modules/%24edgeHub/genid/637660067268563949/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1292 "-" "-" auth_id(-)
<6>2022-02-17T04:26:19Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:26:20Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:26:30Z [INFO] - Querying system resources...
<6>2022-02-17T04:27:03Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:04Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:04Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:04Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:06Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:06Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:07Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:07Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:07Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:07Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:08Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:08Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:27:08Z [INFO] - Edge runtime is running.
<6>2022-02-17T04:27:53Z [INFO] - Checking edge runtime status
<6>2022-02-17T04:28:09Z [INFO] - [work] - - - [2022-02-17 04:28:09.744265752 UTC] "POST /modules/%24edgeHub/genid/637660067268563949/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1292 "-" "-" auth_id(-)
<6>2022-02-17T04:28:09Z [INFO] - [work] - - - [2022-02-17 04:28:09.910882137 UTC] "POST /modules/%24edgeHub/genid/637660067268563949/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1292 "-" "-" auth_id(-)
<6>2022-02-17T04:28:11Z [INFO] - [work] - - - [2022-02-17 04:28:11.106122234 UTC] "POST /modules/%24edgeAgent/genid/637660067268563949/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 2225 "-" "-" auth_id(-)
<6>2022-02-17T04:28:11Z [INFO] - [work] - - - [2022-02-17 04:28:11.136833173 UTC] "POST /modules/%24edgeHub/genid/637660067268563949/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 533 "-" "-" auth_id(-)
<6>2022-02-17T04:28:11Z [INFO] - [work] - - - [2022-02-17 04:28:11.156698330 UTC] "POST /modules/%24edgeHub/genid/637660067268563949/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 421 "-" "-" auth_id(-)
<6>2022-02-17T04:28:11Z [INFO] - Successfully started module simplestupidmodule
<6>2022-02-17T04:28:11Z [INFO] - [mgmt] - - - [2022-02-17 04:28:11.160350957 UTC] "POST /modules/simplestupidmodule/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
<6>2022-02-17T04:28:13Z [INFO] - [mgmt] - - - [2022-02-17 04:28:13.395580836 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1840 "-" "-" auth_id(-)
<6>2022-02-17T04:28:13Z [INFO] - [mgmt] - - - [2022-02-17 04:28:13.430570522 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1840 "-" "-" auth_id(-)
edge-agent logs 

{"log":"2022-02-15 08:19:53 +00:00 Starting Edge Agent\n","stream":"stdout","time":"2022-02-15T08:19:53.334019935Z"}
{"log":"2022-02-15 08:19:53 +00:00 Changing ownership of storage folder: /tmp/edgeAgent to 1000\n","stream":"stdout","time":"2022-02-15T08:19:53.76585367Z"}
{"log":"2022-02-15 08:19:53 +00:00 Changing ownership of management socket: /var/run/iotedge/mgmt.sock\n","stream":"stdout","time":"2022-02-15T08:19:53.826941381Z"}
{"log":"2022-02-15 08:19:58.227 +00:00 Edge Agent Main()\n","stream":"stdout","time":"2022-02-15T08:19:58.968508127Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:06.171 +00:00 [INF] - Initializing Edge Agent.\n","stream":"stdout","time":"2022-02-15T08:20:06.734431403Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:11.782 +00:00 [INF] - Version - 1.1.9.51315016 (17a3a71b5c59f73909912d96987b615a61428dbf)\n","stream":"stdout","time":"2022-02-15T08:20:11.785148318Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:11.805 +00:00 [INF] - \n","stream":"stdout","time":"2022-02-15T08:20:11.807994198Z"}
{"log":"        █████╗ ███████╗██╗   ██╗██████╗ ███████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.808486824Z"}
{"log":"       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝\n","stream":"stdout","time":"2022-02-15T08:20:11.808786487Z"}
{"log":"       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.808987162Z"}
{"log":"       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝\n","stream":"stdout","time":"2022-02-15T08:20:11.809178198Z"}
{"log":"       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.811450969Z"}
{"log":"       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝\n","stream":"stdout","time":"2022-02-15T08:20:11.812641716Z"}
{"log":"\n","stream":"stdout","time":"2022-02-15T08:20:11.823753137Z"}
{"log":" ██╗ ██████╗ ████████╗    ███████╗██████╗  ██████╗ ███████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.825073137Z"}
{"log":" ██║██╔═══██╗╚══██╔══╝    ██╔════╝██╔══██╗██╔════╝ ██╔════╝\n","stream":"stdout","time":"2022-02-15T08:20:11.826162294Z"}
{"log":" ██║██║   ██║   ██║       █████╗  ██║  ██║██║  ███╗█████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.827219258Z"}
{"log":" ██║██║   ██║   ██║       ██╔══╝  ██║  ██║██║   ██║██╔══╝\n","stream":"stdout","time":"2022-02-15T08:20:11.828075354Z"}
{"log":" ██║╚██████╔╝   ██║       ███████╗██████╔╝╚██████╔╝███████╗\n","stream":"stdout","time":"2022-02-15T08:20:11.828921716Z"}
{"log":" ╚═╝ ╚═════╝    ╚═╝       ╚══════╝╚═════╝  ╚═════╝ ╚══════╝\n","stream":"stdout","time":"2022-02-15T08:20:11.829774824Z"}
{"log":"\n","stream":"stdout","time":"2022-02-15T08:20:11.830603643Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:13.074 +00:00 [INF] - Experimental features configuration: {\"Enabled\":false,\"DisableCloudSubscriptions\":false}\n","stream":"stdout","time":"2022-02-15T08:20:13.07678321Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:17.463 +00:00 [INF] - Installing certificates [pseudonym=111-1111, CN=IOT ROOT CA DEVELOPMENT ONLY, OU=CA, O=Cryptera A/S, C=DK:08/26/2036 13:21:56] to Root\n","stream":"stdout","time":"2022-02-15T08:20:17.465956317Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:20.303 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics\n","stream":"stdout","time":"2022-02-15T08:20:20.305912558Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:25.194 +00:00 [INF] - Updating performance metrics every 05m:00s\n","stream":"stdout","time":"2022-02-15T08:20:25.196657425Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:25.322 +00:00 [INF] - Started operation Get system resources\n","stream":"stdout","time":"2022-02-15T08:20:25.324079593Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:25.373 +00:00 [INF] - Collecting metadata metrics\n","stream":"stdout","time":"2022-02-15T08:20:25.375674292Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:27.280 +00:00 [INF] - Set metadata metrics: 1.1.9.51315016 (17a3a71b5c59f73909912d96987b615a61428dbf), {\"Enabled\":false,\"DisableCloudSubscriptions\":false}, {\"OperatingSystemType\":\"linux\",\"Architecture\":\"armv7l\",\"Version\":\"1.1.0\",\"Provisioning\":{\"Type\":\"dps.x509\",\"DynamicReprovisioning\":false},\"ServerVersion\":\"19.03.13\",\"KernelVersion\":\"5.9.8-skylarksecure\",\"OperatingSystem\":\"Buildroot 2020.11.2\",\"NumCpus\":1,\"Virtualized\":\"unknown\"}, True\n","stream":"stdout","time":"2022-02-15T08:20:27.283782533Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:41.584 +00:00 [INF] - Created persistent store at /tmp/edgeAgent\n","stream":"stdout","time":"2022-02-15T08:20:41.590524988Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:42.486 +00:00 [INF] - Started operation Checkpoint Availability\n","stream":"stdout","time":"2022-02-15T08:20:42.488682097Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:42.673 +00:00 [INF] - Started operation refresh twin config\n","stream":"stdout","time":"2022-02-15T08:20:42.675355832Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:43.615 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...\n","stream":"stdout","time":"2022-02-15T08:20:43.620926434Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:45.350 +00:00 [INF] - Registering request handler UploadModuleLogs\n","stream":"stdout","time":"2022-02-15T08:20:45.352728169Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:45.367 +00:00 [INF] - Registering request handler GetModuleLogs\n","stream":"stdout","time":"2022-02-15T08:20:45.368848843Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:45.371 +00:00 [INF] - Registering request handler UploadSupportBundle\n","stream":"stdout","time":"2022-02-15T08:20:45.373691831Z"}
{"log":"\u003c6\u003e 2022-02-15 08:20:45.377 +00:00 [INF] - Registering request handler RestartModule\n","stream":"stdout","time":"2022-02-15T08:20:45.379178578Z"}
{"log":"\u003c4\u003e 2022-02-15 08:21:06.214 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/tmp/edgeAgent/backup.json) instead\n","stream":"stdout","time":"2022-02-15T08:21:06.226291443Z"}
{"log":"\u003c6\u003e 2022-02-15 08:21:07.191 +00:00 [INF] - Obtained edge agent config from backup config file - /tmp/edgeAgent/backup.json\n","stream":"stdout","time":"2022-02-15T08:21:07.193682479Z"}
{"log":"\u003c6\u003e 2022-02-15 08:21:14.178 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only.\n","stream":"stdout","time":"2022-02-15T08:21:14.180673706Z"}
{"log":"\u003c6\u003e 2022-02-15 08:21:17.078 +00:00 [INF] - Plan execution started for deployment 72\n","stream":"stdout","time":"2022-02-15T08:21:17.0805192Z"}
...
...
{"log":"\u003c6\u003e 2022-02-17 04:17:11.196 +00:00 [INF] - Plan execution started for deployment 72\n","stream":"stdout","time":"2022-02-17T04:17:11.547519055Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:12.071 +00:00 [INF] - Executing command: \"Command Group: (\\n  [Stop module simplestupidmodule]\\n  [Start module simplestupidmodule]\\n  [Saving simplestupidmodule to store]\\n)\"\n","stream":"stdout","time":"2022-02-17T04:17:12.203707488Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:12.192 +00:00 [INF] - Executing command: \"Stop module simplestupidmodule\"\n","stream":"stdout","time":"2022-02-17T04:17:12.204662187Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:13.777 +00:00 [INF] - Executing command: \"Start module simplestupidmodule\"\n","stream":"stdout","time":"2022-02-17T04:17:13.780004452Z"}
{"log":"\u003c3\u003e 2022-02-17 04:18:58.916 +00:00 [ERR] - Executing command for operation [\"start\"] failed.\n","stream":"stdout","time":"2022-02-17T04:19:11.722335615Z"}
{"log":"System.OperationCanceledException: The operation was canceled.\n","stream":"stdout","time":"2022-02-17T04:19:12.961784964Z"}
{"log":"   at System.Threading.CancellationToken.ThrowOperationCanceledException()\n","stream":"stdout","time":"2022-02-17T04:19:12.962191133Z"}
{"log":"   at System.Threading.CancellationToken.ThrowIfCancellationRequested()\n","stream":"stdout","time":"2022-02-17T04:19:12.962398844Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)\n","stream":"stdout","time":"2022-02-17T04:19:12.962591808Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)\n","stream":"stdout","time":"2022-02-17T04:19:12.96277494Z"}
{"log":"   at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)\n","stream":"stdout","time":"2022-02-17T04:19:12.965063133Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62\n","stream":"stdout","time":"2022-02-17T04:19:12.966253784Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158\n","stream":"stdout","time":"2022-02-17T04:19:12.96739441Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69\n","stream":"stdout","time":"2022-02-17T04:19:12.969304675Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 40\n","stream":"stdout","time":"2022-02-17T04:19:12.97022747Z"}
{"log":"   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\n","stream":"stdout","time":"2022-02-17T04:19:12.971124531Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.StartModuleAsync(String api_version, String name, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 603\n","stream":"stdout","time":"2022-02-17T04:19:12.972143904Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.\u003c\u003ec__DisplayClass35_0.\u003c\u003cExecute\u003eb__0\u003ed.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 125\n","stream":"stdout","time":"2022-02-17T04:19:12.973069591Z"}
{"log":"--- End of stack trace from previous location where exception was thrown ---\n","stream":"stdout","time":"2022-02-17T04:19:16.440755084Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 126\n","stream":"stdout","time":"2022-02-17T04:19:16.441081253Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 135\n","stream":"stdout","time":"2022-02-17T04:19:16.441267952Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245\n","stream":"stdout","time":"2022-02-17T04:19:16.441450121Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 152\n","stream":"stdout","time":"2022-02-17T04:19:16.441622169Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 178\n","stream":"stdout","time":"2022-02-17T04:19:16.441794892Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67\n","stream":"stdout","time":"2022-02-17T04:19:16.441997976Z"}
{"log":"\u003c3\u003e 2022-02-17 04:19:05.843 +00:00 [ERR] - Executing command for operation [\"Command Group: (\\n  [Stop module simplestupidmodule]\\n  [Start module simplestupidmodule]\\n  [Saving simplestupidmodule to store]\\n)\"] failed.\n","stream":"stdout","time":"2022-02-17T04:19:16.442176289Z"}
{"log":"System.OperationCanceledException: The operation was canceled.\n","stream":"stdout","time":"2022-02-17T04:19:16.442352482Z"}
{"log":"   at System.Threading.CancellationToken.ThrowOperationCanceledException()\n","stream":"stdout","time":"2022-02-17T04:19:16.442512289Z"}
{"log":"   at System.Threading.CancellationToken.ThrowIfCancellationRequested()\n","stream":"stdout","time":"2022-02-17T04:19:16.442670169Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)\n","stream":"stdout","time":"2022-02-17T04:19:16.442828241Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)\n","stream":"stdout","time":"2022-02-17T04:19:16.442985735Z"}
{"log":"   at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)\n","stream":"stdout","time":"2022-02-17T04:19:16.443150843Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62\n","stream":"stdout","time":"2022-02-17T04:19:16.44331441Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158\n","stream":"stdout","time":"2022-02-17T04:19:16.443482121Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69\n","stream":"stdout","time":"2022-02-17T04:19:16.443787374Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 40\n","stream":"stdout","time":"2022-02-17T04:19:16.443982362Z"}
{"log":"   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\n","stream":"stdout","time":"2022-02-17T04:19:16.44418853Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.StartModuleAsync(String api_version, String name, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 603\n","stream":"stdout","time":"2022-02-17T04:19:16.444370988Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.\u003c\u003ec__DisplayClass35_0.\u003c\u003cExecute\u003eb__0\u003ed.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 125\n","stream":"stdout","time":"2022-02-17T04:19:16.444547856Z"}
{"log":"--- End of stack trace from previous location where exception was thrown ---\n","stream":"stdout","time":"2022-02-17T04:19:16.444723952Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 126\n","stream":"stdout","time":"2022-02-17T04:19:16.475742843Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 135\n","stream":"stdout","time":"2022-02-17T04:19:16.476221109Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245\n","stream":"stdout","time":"2022-02-17T04:19:16.477223904Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 152\n","stream":"stdout","time":"2022-02-17T04:19:16.477476819Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 178\n","stream":"stdout","time":"2022-02-17T04:19:16.477668337Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67\n","stream":"stdout","time":"2022-02-17T04:19:16.478054554Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35\n","stream":"stdout","time":"2022-02-17T04:19:16.480616964Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67\n","stream":"stdout","time":"2022-02-17T04:19:16.480884916Z"}
{"log":"\u003c3\u003e 2022-02-17 04:19:07.824 +00:00 [ERR] - Step failed in deployment 72, continuing execution. Failure when running command Command Group: (\n","stream":"stdout","time":"2022-02-17T04:19:16.48125947Z"}
{"log":"  [Stop module simplestupidmodule]\n","stream":"stdout","time":"2022-02-17T04:19:16.48146747Z"}
{"log":"  [Start module simplestupidmodule]\n","stream":"stdout","time":"2022-02-17T04:19:16.48164Z"}
{"log":"  [Saving simplestupidmodule to store]\n","stream":"stdout","time":"2022-02-17T04:19:16.48180106Z"}
{"log":"). Will retry in 00s.\n","stream":"stdout","time":"2022-02-17T04:19:16.481961253Z"}
edge-hub logs 

{"log":"2022-02-15 08:21:43 +00:00 Starting Edge Hub\n","stream":"stdout","time":"2022-02-15T08:21:43.547298955Z"}
{"log":"2022-02-15 08:21:52.868 +00:00 Edge Hub Main()\n","stream":"stdout","time":"2022-02-15T08:21:54.083183291Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:05.859 +00:00 [INF] - Installing certificates [cert_info_goes_here]}
{"log":"\u003c6\u003e 2022-02-15 08:23:09.089 +00:00 [INF] - Installing certificates [cert_info_goes_here]}
{"log":"\u003c6\u003e 2022-02-15 08:23:09.498 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12\n","stream":"stdout","time":"2022-02-15T08:23:09.499834364Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:26.981 +00:00 [INF] - Experimental features configuration: {\"Enabled\":false,\"DisableCloudSubscriptions\":false,\"DisableConnectivityCheck\":false}\n","stream":"stdout","time":"2022-02-15T08:23:27.021608819Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:48.897 +00:00 [INF] - Created persistent store at /tmp/edgeHub\n","stream":"stdout","time":"2022-02-15T08:23:48.903498165Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.000 +00:00 [INF] - Initializing Edge Hub\n","stream":"stdout","time":"2022-02-15T08:23:53.002759466Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.017 +00:00 [INF] - \n","stream":"stdout","time":"2022-02-15T08:23:53.095926598Z"}
{"log":"        █████╗ ███████╗██╗   ██╗██████╗ ███████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.096381827Z"}
{"log":"       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝\n","stream":"stdout","time":"2022-02-15T08:23:53.096620574Z"}
{"log":"       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.097300478Z"}
{"log":"       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝\n","stream":"stdout","time":"2022-02-15T08:23:53.097573827Z"}
{"log":"       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.097772671Z"}
{"log":"       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝\n","stream":"stdout","time":"2022-02-15T08:23:53.097952141Z"}
{"log":"\n","stream":"stdout","time":"2022-02-15T08:23:53.098120815Z"}
{"log":" ██╗ ██████╗ ████████╗    ███████╗██████╗  ██████╗ ███████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.09827937Z"}
{"log":" ██║██╔═══██╗╚══██╔══╝    ██╔════╝██╔══██╗██╔════╝ ██╔════╝\n","stream":"stdout","time":"2022-02-15T08:23:53.098451418Z"}
{"log":" ██║██║   ██║   ██║       █████╗  ██║  ██║██║  ███╗█████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.098623562Z"}
{"log":" ██║██║   ██║   ██║       ██╔══╝  ██║  ██║██║   ██║██╔══╝\n","stream":"stdout","time":"2022-02-15T08:23:53.098790213Z"}
{"log":" ██║╚██████╔╝   ██║       ███████╗██████╔╝╚██████╔╝███████╗\n","stream":"stdout","time":"2022-02-15T08:23:53.098957442Z"}
{"log":" ╚═╝ ╚═════╝    ╚═╝       ╚══════╝╚═════╝  ╚═════╝ ╚══════╝\n","stream":"stdout","time":"2022-02-15T08:23:53.099125153Z"}
{"log":"\n","stream":"stdout","time":"2022-02-15T08:23:53.09928949Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.127 +00:00 [INF] - Version - 1.1.9.51315016 (17a3a71b5c59f73909912d96987b615a61428dbf)\n","stream":"stdout","time":"2022-02-15T08:23:53.129374984Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.132 +00:00 [INF] - OptimizeForPerformance=False\n","stream":"stdout","time":"2022-02-15T08:23:53.133818165Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.146 +00:00 [INF] - MessageAckTimeoutSecs=30\n","stream":"stdout","time":"2022-02-15T08:23:53.148037442Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:53.257 +00:00 [INF] - Loaded server certificate with expiration date of \"2022-05-16T08:22:18.0000000+00:00\"\n","stream":"stdout","time":"2022-02-15T08:23:53.478142791Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:54.052 +00:00 [INF] - Using Asp Net server for metrics\n","stream":"stdout","time":"2022-02-15T08:23:54.054073104Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:59.687 +00:00 [INF] - Started task to cleanup processed and stale messages\n","stream":"stdout","time":"2022-02-15T08:23:59.68930867Z"}
{"log":"\u003c6\u003e 2022-02-15 08:23:59.701 +00:00 [INF] - Created new message store\n","stream":"stdout","time":"2022-02-15T08:23:59.75771532Z"}
{"log":"\u003c6\u003e 2022-02-15 08:24:01.335 +00:00 [INF] - Created device scope identities cache\n","stream":"stdout","time":"2022-02-15T08:24:01.337266356Z"}
{"log":"\u003c6\u003e 2022-02-15 08:24:01.952 +00:00 [INF] - Starting refresh of device scope identities cache\n","stream":"stdout","time":"2022-02-15T08:24:01.954675416Z"}
{"log":"\u003c6\u003e 2022-02-15 08:24:07.949 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00\n","stream":"stdout","time":"2022-02-15T08:24:07.95198809Z"}
{"log":"\u003c6\u003e 2022-02-15 08:24:15.000 +00:00 [INF] - Initialized storing twin manager\n","stream":"stdout","time":"2022-02-15T08:24:15.003454595Z"}
{"log":"\u003c6\u003e 2022-02-15 08:24:17.228 +00:00 [INF] - Initializing configuration\n","stream":"stdout","time":"2022-02-15T08:24:17.461126498Z"}
...
...
{"log":"\u003c4\u003e 2022-02-17 04:16:38.870 +00:00 [WRN] - Closing connection for device: registration_id/simplestupidmodule, scope: ExceptionCaught, System.Net.Sockets.SocketException (104): Connection reset by peer\n","stream":"stdout","time":"2022-02-17T04:16:38.872503445Z"}
{"log":"   at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoReadBytes(IByteBuffer byteBuf)\n","stream":"stdout","time":"2022-02-17T04:16:38.875427012Z"}
{"log":"   at DotNetty.Transport.Channels.Sockets.AbstractSocketByteChannel.SocketByteChannelUnsafe.FinishRead(SocketChannelAsyncOperation operation), 1a8d4bcb\n","stream":"stdout","time":"2022-02-17T04:16:38.881021518Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:38.878 +00:00 [INF] - Disposing MessagingServiceClient for device Id registration_id/simplestupidmodule because of exception - System.Net.Sockets.SocketException (104): Connection reset by peer\n","stream":"stdout","time":"2022-02-17T04:16:38.894959445Z"}
{"log":"   at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoReadBytes(IByteBuffer byteBuf)\n","stream":"stdout","time":"2022-02-17T04:16:38.899536024Z"}
{"log":"   at DotNetty.Transport.Channels.Sockets.AbstractSocketByteChannel.SocketByteChannelUnsafe.FinishRead(SocketChannelAsyncOperation operation)\n","stream":"stdout","time":"2022-02-17T04:16:38.899920987Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:38.900 +00:00 [INF] - Setting device proxy inactive for device Id registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:16:38.90241024Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:38.903 +00:00 [INF] - Removing device connection for device registration_id/simplestupidmodule with removeCloudConnection flag 'True'.\n","stream":"stdout","time":"2022-02-17T04:16:38.905325421Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:38.998 +00:00 [INF] - Closing receiver in cloud proxy af02104a-5dcd-4a06-a0be-a7f5fa31d882 for registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:16:38.99981853Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:39.132 +00:00 [INF] - Closed cloud proxy af02104a-5dcd-4a06-a0be-a7f5fa31d882 for registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:16:39.133797036Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:39.142 +00:00 [INF] - Device connection removed for device registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:16:39.144095734Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:39.209 +00:00 [INF] - Remove device connection for device registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:16:39.215632602Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:41.886 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:16:41.888128891Z"}
{"log":"\u003c6\u003e 2022-02-17 04:16:55.858 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:16:56.33343472Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:16.708 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:17:16.710746138Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:16.714 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub\n","stream":"stdout","time":"2022-02-17T04:17:16.729771199Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:17.031 +00:00 [INF] - Cleaned up 6 messages from queue for endpoint iothub and 6 messages from message store.\n","stream":"stdout","time":"2022-02-17T04:17:17.098301223Z"}
{"log":"\u003c6\u003e 2022-02-17 04:17:42.781 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:17:42.873051869Z"}
{"log":"\u003c6\u003e 2022-02-17 04:18:08.413 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:18:09.730393167Z"}
{"log":"\u003c6\u003e 2022-02-17 04:18:28.623 +00:00 [INF] - Updated reported properties for registration_id/$edgeHub\n","stream":"stdout","time":"2022-02-17T04:18:29.703916923Z"}
{"log":"\u003c4\u003e 2022-02-17 04:20:13.809 +00:00 [WRN] - Error in pump to sync reported properties to cloud\n","stream":"stdout","time":"2022-02-17T04:20:34.265897338Z"}
{"log":"System.InvalidOperationException: Value not found in store\n","stream":"stdout","time":"2022-02-17T04:20:47.52627083Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Option`1.Expect[TException](Func`1 exception) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/Option.cs:line 117\n","stream":"stdout","time":"2022-02-17T04:20:47.735796517Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Storage.EntityStore`2.Update(TK key, Func`2 updator, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Storage/EntityStore.cs:line 93\n","stream":"stdout","time":"2022-02-17T04:20:47.736230059Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.ReportedPropertiesStore.\u003c\u003ec__DisplayClass12_0.\u003c\u003cSyncToCloud\u003eb__2\u003ed.MoveNext() in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/ReportedPropertiesStore.cs:line 93\n","stream":"stdout","time":"2022-02-17T04:20:47.736446155Z"}
{"log":"--- End of stack trace from previous location where exception was thrown ---\n","stream":"stdout","time":"2022-02-17T04:20:47.736634782Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.ReportedPropertiesStore.\u003c\u003ec__DisplayClass12_0.\u003c\u003cSyncToCloud\u003eb__1\u003ed.MoveNext() in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/ReportedPropertiesStore.cs:line 94\n","stream":"stdout","time":"2022-02-17T04:20:47.736801721Z"}
{"log":"--- End of stack trace from previous location where exception was thrown ---\n","stream":"stdout","time":"2022-02-17T04:20:47.736982252Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.ReportedPropertiesStore.SyncToCloud(String id) in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/ReportedPropertiesStore.cs:line 101\n","stream":"stdout","time":"2022-02-17T04:20:47.737145818Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.ReportedPropertiesStore.SyncToCloud() in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/ReportedPropertiesStore.cs:line 119\n","stream":"stdout","time":"2022-02-17T04:20:47.737315071Z"}
{"log":"\u003c6\u003e 2022-02-17 04:20:59.243 +00:00 [INF] - Entering periodic task to reauthenticate connected clients\n","stream":"stdout","time":"2022-02-17T04:21:03.462361237Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:49.113 +00:00 [INF] - Starting compaction of stores\n","stream":"stdout","time":"2022-02-17T04:24:10.407886703Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:49.116 +00:00 [INF] - Starting compaction of store iothub\n","stream":"stdout","time":"2022-02-17T04:24:11.921704824Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.025 +00:00 [INF] - Starting compaction of store EdgeTwin\n","stream":"stdout","time":"2022-02-17T04:24:11.922197257Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.027 +00:00 [INF] - Starting compaction of store DeviceScopeCache\n","stream":"stdout","time":"2022-02-17T04:24:11.922423956Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.027 +00:00 [INF] - Starting compaction of store MetadataStore\n","stream":"stdout","time":"2022-02-17T04:24:11.922618558Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.028 +00:00 [INF] - Starting compaction of store messages\n","stream":"stdout","time":"2022-02-17T04:24:11.922807281Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.029 +00:00 [INF] - Starting compaction of store twins\n","stream":"stdout","time":"2022-02-17T04:24:11.922987426Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.029 +00:00 [INF] - Starting compaction of store checkpoints\n","stream":"stdout","time":"2022-02-17T04:24:11.923166896Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.030 +00:00 [INF] - Starting compaction of store sessions\n","stream":"stdout","time":"2022-02-17T04:24:11.923348293Z"}
{"log":"\u003c6\u003e 2022-02-17 04:23:50.031 +00:00 [INF] - Starting compaction of store default\n","stream":"stdout","time":"2022-02-17T04:24:11.923525546Z"}
{"log":"\u003c4\u003e 2022-02-17 04:23:46.103 +00:00 [WRN] - Error handling device connected event for device registration_id/simplestupidmodule\n","stream":"stdout","time":"2022-02-17T04:24:11.923703185Z"}
{"log":"System.OperationCanceledException: The operation was canceled.\n","stream":"stdout","time":"2022-02-17T04:24:11.923881016Z"}
{"log":"   at System.Threading.CancellationToken.ThrowOperationCanceledException()\n","stream":"stdout","time":"2022-02-17T04:24:11.924238703Z"}
{"log":"   at System.Threading.CancellationToken.ThrowIfCancellationRequested()\n","stream":"stdout","time":"2022-02-17T04:24:11.924431667Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)\n","stream":"stdout","time":"2022-02-17T04:24:11.924600149Z"}
{"log":"   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)\n","stream":"stdout","time":"2022-02-17T04:24:11.924766607Z"}
{"log":"   at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)\n","stream":"stdout","time":"2022-02-17T04:24:11.92511851Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62\n","stream":"stdout","time":"2022-02-17T04:24:11.925356775Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158\n","stream":"stdout","time":"2022-02-17T04:24:11.925624438Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69\n","stream":"stdout","time":"2022-02-17T04:24:11.925865884Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 40\n","stream":"stdout","time":"2022-02-17T04:24:11.926047281Z"}
{"log":"   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)\n","stream":"stdout","time":"2022-02-17T04:24:11.926219619Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.GeneratedCode.HttpWorkloadClient.EncryptAsync(String api_version, String name, String genid, EncryptRequest payload, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2019_01_30/generatedCode/HttpWorkloadClient.cs:line 229\n","stream":"stdout","time":"2022-02-17T04:24:11.926498173Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128\n","stream":"stdout","time":"2022-02-17T04:24:11.926688342Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 79\n","stream":"stdout","time":"2022-02-17T04:24:11.926856727Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.HandleException(Exception ex, String operation) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2019_01_30/WorkloadClient.cs:line 119\n","stream":"stdout","time":"2022-02-17T04:24:11.927028197Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 79\n","stream":"stdout","time":"2022-02-17T04:24:11.927198221Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.EncryptAsync(String initializationVector, String plainText) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2019_01_30/WorkloadClient.cs:line 67\n","stream":"stdout","time":"2022-02-17T04:24:11.927535956Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Storage.UpdatableEncryptedStore`2.EncryptValue(String value) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Storage/UpdatableEncryptedStore.cs:line 25\n","stream":"stdout","time":"2022-02-17T04:24:11.927739137Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Storage.EncryptedStore`2.Put(TK key, TV value, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Storage/EncryptedStore.cs:line 42\n","stream":"stdout","time":"2022-02-17T04:24:11.927916486Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Storage.EntityStore`2.\u003c\u003ec__DisplayClass22_0.\u003c\u003cPutOrUpdate\u003eb__1\u003ed.MoveNext() in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Storage/EntityStore.cs:line 116\n","stream":"stdout","time":"2022-02-17T04:24:11.928089113Z"}
{"log":"--- End of stack trace from previous location where exception was thrown ---\n","stream":"stdout","time":"2022-02-17T04:24:11.928264149Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Storage.EntityStore`2.PutOrUpdate(TK key, TV value, Func`2 updator, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Storage/EntityStore.cs:line 119\n","stream":"stdout","time":"2022-02-17T04:24:11.928426077Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.ReportedPropertiesStore.Update(String id, TwinCollection patch) in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/ReportedPropertiesStore.cs:line 51\n","stream":"stdout","time":"2022-02-17T04:24:11.928594944Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.StoringTwinManager.UpdateReportedPropertiesAsync(String id, IMessage twinCollection) in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/StoringTwinManager.cs:line 154\n","stream":"stdout","time":"2022-02-17T04:24:11.928762077Z"}
{"log":"   at Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubConnection.DeviceConnected(Object sender, IIdentity device) in /mnt/vss/_work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/EdgeHubConnection.cs:line 109\n","stream":"stdout","time":"2022-02-17T04:24:11.928961498Z"}
{"log":"\u003c6\u003e 2022-02-17 04:24:47.080 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub\n","stream":"stdout","time":"2022-02-17T04:25:07.144703273Z"}
{"log":"\u003c6\u003e 2022-02-17 04:24:47.856 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store.\n","stream":"stdout","time":"2022-02-17T04:25:07.177757153Z"}
{"log":"\u003c6\u003e 2022-02-17 04:25:59.256 +00:00 [INF] - Entering periodic task to reauthenticate connected clients\n","stream":"stdout","time":"2022-02-17T04:26:36.604310103Z"}
Azure IoT Explorer logs (listening to msgs send to iothub from 2022-02-17 04:00:00 and forward) 


Thu Feb 17 2022 04:08:39 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:08:39 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {
    "mqtt-dup": "true"
  }
}
Thu Feb 17 2022 04:08:37 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:08:37 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:07:20 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:07:20 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {
    "mqtt-dup": "true"
  }
}
Thu Feb 17 2022 04:06:12 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:06:12 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {
    "mqtt-dup": "true"
  }
}
Thu Feb 17 2022 04:05:09 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:05:09 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:04:09 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:04:09 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:03:03 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:03:03 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:02:03 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:02:03 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:01:03 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:01:03 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}
Thu Feb 17 2022 04:00:03 GMT+0100 (Centraleuropæisk normaltid):
{
  "body": "im alive",
  "enqueuedTime": "Thu Feb 17 2022 04:00:03 GMT+0100 (Centraleuropæisk normaltid)",
  "properties": {}
}

If you want more logs just tell me. There was no more room in the comment.

Additional Information

I have been dealing with this kind of problem for a while, but receiving the property mqtt-dub: true on some of the last msgs to the iothub before failing was new to me. I cannot find anything in the documentation regarding this. Can you tell me what this means?

Despite not having send a msg since 2022-02-17 04:08:39, and not having written to its logs since 2022-02-17 04:32:43, my custom module simplestupidmodule has been running for at least a day.

Output of iotedge list 

~ # iotedge list
NAME                STATUS           DESCRIPTION      CONFIG
edgeAgent           running          Up 3 days        mcr.microsoft.com/azureiotedge-agent:1.1
edgeHub             running          Up 3 days        mcr.microsoft.com/azureiotedge-hub:1.1
simplestupidmodule  running          Up a day         someregistry.azurecr.io/simplestupidmodule:0.0.13-arm32v7

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 29 (12 by maintainers)

Most upvoted comments

@nlcamp Actually i was running it as root. Should i try with a non-root user instead?

Ah cheers. I will try to run the same setup with aziot-iot-device version 2.10.0 instead. I’ll get back to you in a couple of days when it has been running for some time.

+1
henrik2424 on Mar 16, 2022

@nlcamp Thank you for the reply. I will try the different approaches when i get to the office on monday.

My create options is ended up as a result of trying different things. However i can ping the dns server. image

I’ll give you an update throughout next week.

+1
henrik2424 on Mar 3, 2022
Read more comments on GitHub
← iotedge: Simple C# custom module stops sending mqtt msgs and cannot recover
iotedge: TPM Provisioning doesn't work for iotedge version 1.4 unless upgrade from version 1.3 →