search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.46k stars 460 forks source link

Memory Leak in an embedded Linux environment #4545

Closed AdrienCos closed 3 years ago

AdrienCos commented 3 years ago

Expected Behavior

The device on which IoT Edge is running should have a constant memory use, after a post-boot transition phase.

Current Behavior

The memory use of the device keeps increasing until it becomes unresponsive due to low memory availability.

Steps to Reproduce

  1. Install IoT Edge on an embedded Linux device (Raspberry Pi CM3+ in our case)
  2. Add the edgeHub and edgeAgent modules to its deployment
  3. Start IoT Edge
  4. Observe the memory usage increase over the course of multiple days, until the device becomes unresponsive to SSH connections.

Context (Environment)

Output of iotedge check

Click here ``` 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 - OK ‼ latest security daemon - Warning Installed IoT Edge daemon has version 1.0.10 but 1.1.0 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ host time is close to real time - OK √ container time is close to host time - OK √ DNS server - OK ‼ production readiness: certificates - Warning The Edge device is using self-signed automatically-generated development certificates. They will expire in 5469 days (at 2036-02-22 17:47:54 UTC) causing module-to-module and downstream device communication to fail on an active deployment. After the certs have expired, restarting the IoT Edge daemon will trigger it to generate new development certs. Please consider using production certificates instead. See https://aka.ms/iotedge-prod-checklist-certs for best practices. √ production readiness: container engine - OK ‼ production readiness: logs policy - Warning Container engine is not configured to rotate module logs which may cause it run out of disk space. Please see https://aka.ms/iotedge-prod-checklist-logs for best practices. You can ignore this warning if you are setting log policy per module in the Edge deployment. ‼ 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 - OK √ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the default network can connect to IoT Hub MQTT port - OK √ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK √ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK 19 check(s) succeeded. 5 check(s) raised warnings. Re-run with --verbose for more details. ```

Device Information

Runtime Versions

Logs

These logs correspond to the startup sequence of iotedge on a nominal device, that exhibits a memory leak.

iotedged logs ``` Mar 03 14:29:43 redacted_hostname systemd[1]: Starting Azure IoT Edge daemon... Mar 03 14:29:43 redacted_hostname systemd[1]: Started Azure IoT Edge daemon. Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Starting Azure IoT Edge Security Daemon Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Version - 1.0.10 Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Using config file: /etc/iotedge/config.yaml Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Configuring /var/lib/iotedge as the home directory. Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Configuring certificates... Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Transparent gateway certificates not found, operating in quick start mode... Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Finished configuring provisioning environment variables and certificates. Mar 03 14:29:43 redacted_hostname iotedged[1249]: 2021-03-03T13:29:43Z [INFO] - Initializing hsm... Mar 03 14:29:55 redacted_hostname iotedged[1249]: 2021-03-03T13:29:55Z [INFO] - Finished initializing hsm. Mar 03 14:29:55 redacted_hostname iotedged[1249]: 2021-03-03T13:29:55Z [INFO] - Provisioning edge device... Mar 03 14:29:55 redacted_hostname iotedged[1249]: 2021-03-03T13:29:55Z [INFO] - Starting provisioning edge device via TPM... Mar 03 14:29:55 redacted_hostname iotedged[1249]: 2021-03-03T13:29:55Z [INFO] - Starting DPS registration with scope_id "redacted_scope", registration_id "redacted_id" Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - DPS registration assigned device "redacted_hostname" in hub "redacted-iothub.azure-devices.net" Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Finished provisioning edge device. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Initializing the module runtime... Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Initializing module runtime... Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Using runtime network id azure-iot-edge Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Successfully initialized module runtime Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Finished initializing the module runtime. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Stopping all modules... Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Finished stopping modules. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Detecting if configuration file has changed... Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Change to configuration file detected. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Removing all modules... Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Finished removing modules. Mar 03 14:30:10 redacted_hostname iotedged[1249]: 2021-03-03T13:30:10Z [INFO] - Edge issuer CA expiration date: 2036-02-28T13:29:48Z Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Starting management API... Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Starting workload API... Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Starting watchdog with 60 second frequency... Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API. Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Checking edge runtime status Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - Creating and starting edge runtime module edgeAgent Mar 03 14:30:17 redacted_hostname iotedged[1249]: 2021-03-03T13:30:17Z [INFO] - [mgmt] - - - [2021-03-03 13:30:17.842024039 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [INFO] - Updating identity for module $edgeAgent Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0... Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - Could not pull image mcr.microsoft.com/azureiotedge-agent:1.0 Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - caused by: Get https://mcr.microsoft.com/v2/: dial tcp: lookup mcr.microsoft.com on [::1]:53: read udp [::1]:51409->[::1]:53: read: connection refused Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - Error in watchdog when checking for edge runtime status: Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - A module runtime error occurred. Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - caused by: Could not pull image mcr.microsoft.com/azureiotedge-agent:1.0 Mar 03 14:30:18 redacted_hostname iotedged[1249]: 2021-03-03T13:30:18Z [WARN] - caused by: Get https://mcr.microsoft.com/v2/: dial tcp: lookup mcr.microsoft.com on [::1]:53: read udp [::1]:51409->[::1]:53: read: connection refused Mar 03 14:31:10 redacted_hostname iotedged[1249]: 2021-03-03T13:31:10Z [INFO] - [mgmt] - - - [2021-03-03 13:31:10.858214036 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:31:17 redacted_hostname iotedged[1249]: 2021-03-03T13:31:17Z [INFO] - Checking edge runtime status Mar 03 14:31:17 redacted_hostname iotedged[1249]: 2021-03-03T13:31:17Z [INFO] - Creating and starting edge runtime module edgeAgent Mar 03 14:31:17 redacted_hostname iotedged[1249]: 2021-03-03T13:31:17Z [INFO] - Updating identity for module $edgeAgent Mar 03 14:31:18 redacted_hostname iotedged[1249]: 2021-03-03T13:31:18Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0... Mar 03 14:32:07 redacted_hostname iotedged[1249]: 2021-03-03T13:32:07Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0 Mar 03 14:32:07 redacted_hostname iotedged[1249]: 2021-03-03T13:32:07Z [INFO] - Creating module edgeAgent... Mar 03 14:32:09 redacted_hostname iotedged[1249]: 2021-03-03T13:32:09Z [INFO] - Successfully created module edgeAgent Mar 03 14:32:09 redacted_hostname iotedged[1249]: 2021-03-03T13:32:09Z [INFO] - Starting module edgeAgent... Mar 03 14:32:11 redacted_hostname iotedged[1249]: 2021-03-03T13:32:11Z [INFO] - Successfully started module edgeAgent Mar 03 14:32:11 redacted_hostname iotedged[1249]: 2021-03-03T13:32:11Z [INFO] - [mgmt] - - - [2021-03-03 13:32:11.384362823 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:32:14 redacted_hostname iotedged[1249]: 2021-03-03T13:32:14Z [INFO] - [work] - - - [2021-03-03 13:32:14.622914926 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:32:16 redacted_hostname iotedged[1249]: 2021-03-03T13:32:16Z [INFO] - Querying system info... Mar 03 14:32:16 redacted_hostname iotedged[1249]: none Mar 03 14:32:16 redacted_hostname iotedged[1249]: 2021-03-03T13:32:16Z [INFO] - Successfully queried system info Mar 03 14:32:16 redacted_hostname iotedged[1249]: 2021-03-03T13:32:16Z [INFO] - [mgmt] - - - [2021-03-03 13:32:16.649810653 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Mar 03 14:32:17 redacted_hostname iotedged[1249]: 2021-03-03T13:32:17Z [INFO] - Checking edge runtime status Mar 03 14:32:17 redacted_hostname iotedged[1249]: 2021-03-03T13:32:17Z [INFO] - Edge runtime is running. Mar 03 14:32:20 redacted_hostname iotedged[1249]: 2021-03-03T13:32:20Z [INFO] - Querying system info... Mar 03 14:32:20 redacted_hostname iotedged[1249]: none Mar 03 14:32:20 redacted_hostname iotedged[1249]: 2021-03-03T13:32:20Z [INFO] - Successfully queried system info Mar 03 14:32:20 redacted_hostname iotedged[1249]: 2021-03-03T13:32:20Z [INFO] - [mgmt] - - - [2021-03-03 13:32:20.361963461 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Mar 03 14:32:20 redacted_hostname iotedged[1249]: 2021-03-03T13:32:20Z [INFO] - [mgmt] - - - [2021-03-03 13:32:20.883846733 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-) Mar 03 14:32:21 redacted_hostname iotedged[1249]: 2021-03-03T13:32:21Z [INFO] - [work] - - - [2021-03-03 13:32:21.140759386 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Mar 03 14:32:23 redacted_hostname iotedged[1249]: 2021-03-03T13:32:23Z [INFO] - [work] - - - [2021-03-03 13:32:23.588487800 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 12989 "-" "-" auth_id(-) Mar 03 14:32:24 redacted_hostname iotedged[1249]: 2021-03-03T13:32:24Z [INFO] - [mgmt] - - - [2021-03-03 13:32:24.179885622 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1550 "-" "-" auth_id(-) Mar 03 14:32:28 redacted_hostname iotedged[1249]: 2021-03-03T13:32:28Z [INFO] - [mgmt] - - - [2021-03-03 13:32:28.936162679 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-) Mar 03 14:32:28 redacted_hostname iotedged[1249]: 2021-03-03T13:32:28Z [INFO] - [mgmt] - - - [2021-03-03 13:32:28.950608724 UTC] "PUT /identities/azureblobstorageoniotedge?api-version=2020-07-07 HTTP/1.1" 200 OK 115 "-" "-" auth_id(-) Mar 03 14:32:28 redacted_hostname iotedged[1249]: 2021-03-03T13:32:28Z [INFO] - [mgmt] - - - [2021-03-03 13:32:28.982062931 UTC] "PUT /identities/ECSManager?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Mar 03 14:32:29 redacted_hostname iotedged[1249]: 2021-03-03T13:32:29Z [INFO] - [mgmt] - - - [2021-03-03 13:32:29.225766954 UTC] "PUT /identities/FsmManager?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Mar 03 14:32:29 redacted_hostname iotedged[1249]: 2021-03-03T13:32:29Z [INFO] - [mgmt] - - - [2021-03-03 13:32:29.639171665 UTC] "PUT /identities/Average?api-version=2020-07-07 HTTP/1.1" 200 OK 97 "-" "-" auth_id(-) Mar 03 14:32:30 redacted_hostname iotedged[1249]: 2021-03-03T13:32:30Z [INFO] - [mgmt] - - - [2021-03-03 13:32:30.418182875 UTC] "PUT /identities/BlueTooth?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Mar 03 14:32:31 redacted_hostname iotedged[1249]: 2021-03-03T13:32:31Z [INFO] - [mgmt] - - - [2021-03-03 13:32:31.290279365 UTC] "PUT /identities/ModbusMapper?api-version=2020-07-07 HTTP/1.1" 200 OK 102 "-" "-" auth_id(-) Mar 03 14:32:32 redacted_hostname iotedged[1249]: 2021-03-03T13:32:32Z [INFO] - [mgmt] - - - [2021-03-03 13:32:32.079532940 UTC] "PUT /identities/Modbus?api-version=2020-07-07 HTTP/1.1" 200 OK 96 "-" "-" auth_id(-) Mar 03 14:32:32 redacted_hostname iotedged[1249]: 2021-03-03T13:32:32Z [INFO] - [mgmt] - - - [2021-03-03 13:32:32.134285889 UTC] "PUT /identities/ActuatorMonitor?api-version=2020-07-07 HTTP/1.1" 200 OK 105 "-" "-" auth_id(-) Mar 03 14:32:33 redacted_hostname iotedged[1249]: 2021-03-03T13:32:33Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10... Mar 03 14:33:16 redacted_hostname iotedged[1249]: 2021-03-03T13:33:16Z [INFO] - Querying system resources... Mar 03 14:33:17 redacted_hostname iotedged[1249]: 2021-03-03T13:33:17Z [INFO] - Checking edge runtime status Mar 03 14:33:17 redacted_hostname iotedged[1249]: 2021-03-03T13:33:17Z [INFO] - Edge runtime is running. Mar 03 14:33:17 redacted_hostname iotedged[1249]: 2021-03-03T13:33:17Z [INFO] - [mgmt] - - - [2021-03-03 13:33:17.620092937 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 2536 "-" "-" auth_id(-) Mar 03 14:33:22 redacted_hostname iotedged[1249]: 2021-03-03T13:33:22Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10 Mar 03 14:33:22 redacted_hostname iotedged[1249]: 2021-03-03T13:33:22Z [INFO] - [mgmt] - - - [2021-03-03 13:33:22.910738607 UTC] "POST /modules/edgeAgent/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:33:23 redacted_hostname iotedged[1249]: 2021-03-03T13:33:23Z [INFO] - Updating and starting module edgeAgent Mar 03 14:33:23 redacted_hostname iotedged[1249]: 2021-03-03T13:33:23Z [INFO] - Removing module edgeAgent... Mar 03 14:33:28 redacted_hostname iotedged[1249]: 2021-03-03T13:33:28Z [INFO] - [mgmt] - - - [2021-03-03 13:33:28.665675288 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 611 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:33:28 redacted_hostname iotedged[1249]: 2021-03-03T13:33:28Z [INFO] - Successfully removed module edgeAgent Mar 03 14:33:28 redacted_hostname iotedged[1249]: 2021-03-03T13:33:28Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10... Mar 03 14:33:29 redacted_hostname iotedged[1249]: 2021-03-03T13:33:29Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10 Mar 03 14:33:29 redacted_hostname iotedged[1249]: 2021-03-03T13:33:29Z [INFO] - Creating module edgeAgent... Mar 03 14:33:29 redacted_hostname iotedged[1249]: 2021-03-03T13:33:29Z [INFO] - Successfully created module edgeAgent Mar 03 14:33:29 redacted_hostname iotedged[1249]: 2021-03-03T13:33:29Z [INFO] - Starting module edgeAgent Mar 03 14:33:29 redacted_hostname iotedged[1249]: 2021-03-03T13:33:29Z [INFO] - Starting module edgeAgent... Mar 03 14:33:31 redacted_hostname iotedged[1249]: 2021-03-03T13:33:31Z [INFO] - Successfully started module edgeAgent Mar 03 14:33:31 redacted_hostname iotedged[1249]: 2021-03-03T13:33:31Z [INFO] - [mgmt] - - - [2021-03-03 13:33:31.332345835 UTC] "PUT /modules/edgeAgent?api-version=2020-07-07&start=true HTTP/1.1" 200 OK 1596 "-" "-" auth_id(-) Mar 03 14:33:31 redacted_hostname iotedged[1249]: 2021-03-03T13:33:31Z [ERR!] - server connection error: (unknown) Mar 03 14:33:31 redacted_hostname iotedged[1249]: 2021-03-03T13:33:31Z [ERR!] - error writing a body to connection: Broken pipe (os error 32) Mar 03 14:33:34 redacted_hostname iotedged[1249]: 2021-03-03T13:33:34Z [INFO] - [work] - - - [2021-03-03 13:33:34.613702742 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:33:36 redacted_hostname iotedged[1249]: 2021-03-03T13:33:36Z [INFO] - Querying system info... Mar 03 14:33:36 redacted_hostname iotedged[1249]: none Mar 03 14:33:36 redacted_hostname iotedged[1249]: 2021-03-03T13:33:36Z [INFO] - Successfully queried system info Mar 03 14:33:36 redacted_hostname iotedged[1249]: 2021-03-03T13:33:36Z [INFO] - [mgmt] - - - [2021-03-03 13:33:36.702292701 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Mar 03 14:33:40 redacted_hostname iotedged[1249]: 2021-03-03T13:33:40Z [INFO] - Querying system info... Mar 03 14:33:40 redacted_hostname iotedged[1249]: none Mar 03 14:33:40 redacted_hostname iotedged[1249]: 2021-03-03T13:33:40Z [INFO] - Successfully queried system info Mar 03 14:33:40 redacted_hostname iotedged[1249]: 2021-03-03T13:33:40Z [INFO] - [mgmt] - - - [2021-03-03 13:33:40.520795226 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Mar 03 14:33:40 redacted_hostname iotedged[1249]: 2021-03-03T13:33:40Z [INFO] - [work] - - - [2021-03-03 13:33:40.839089993 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Mar 03 14:33:40 redacted_hostname iotedged[1249]: 2021-03-03T13:33:40Z [INFO] - [mgmt] - - - [2021-03-03 13:33:40.935913664 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 725 "-" "-" auth_id(-) Mar 03 14:33:43 redacted_hostname iotedged[1249]: 2021-03-03T13:33:43Z [INFO] - [work] - - - [2021-03-03 13:33:43.322042600 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 12989 "-" "-" auth_id(-) Mar 03 14:33:43 redacted_hostname iotedged[1249]: 2021-03-03T13:33:43Z [INFO] - [mgmt] - - - [2021-03-03 13:33:43.949413711 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1550 "-" "-" auth_id(-) Mar 03 14:33:47 redacted_hostname iotedged[1249]: 2021-03-03T13:33:47Z [INFO] - [mgmt] - - - [2021-03-03 13:33:47.617445138 UTC] "PUT /identities/ECSManager?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Mar 03 14:33:50 redacted_hostname iotedged[1249]: 2021-03-03T13:33:50Z [INFO] - [mgmt] - - - [2021-03-03 13:33:50.114634616 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-) Mar 03 14:33:50 redacted_hostname iotedged[1249]: 2021-03-03T13:33:50Z [INFO] - [mgmt] - - - [2021-03-03 13:33:50.370219839 UTC] "PUT /identities/Average?api-version=2020-07-07 HTTP/1.1" 200 OK 97 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.004208453 UTC] "PUT /identities/BlueTooth?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.780505771 UTC] "PUT /identities/ModbusMapper?api-version=2020-07-07 HTTP/1.1" 200 OK 102 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.780505823 UTC] "PUT /identities/Modbus?api-version=2020-07-07 HTTP/1.1" 200 OK 96 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.780505771 UTC] "PUT /identities/azureblobstorageoniotedge?api-version=2020-07-07 HTTP/1.1" 200 OK 115 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.780505719 UTC] "PUT /identities/FsmManager?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Mar 03 14:33:51 redacted_hostname iotedged[1249]: 2021-03-03T13:33:51Z [INFO] - [mgmt] - - - [2021-03-03 13:33:51.826149137 UTC] "PUT /identities/ActuatorMonitor?api-version=2020-07-07 HTTP/1.1" 200 OK 105 "-" "-" auth_id(-) Mar 03 14:33:52 redacted_hostname iotedged[1249]: 2021-03-03T13:33:52Z [INFO] - Pulling image redacted_registry.azurecr.io/modbusmapper:2.0.0-20210301080123PM-arm32v7... Mar 03 14:34:17 redacted_hostname iotedged[1249]: 2021-03-03T13:34:17Z [INFO] - Checking edge runtime status Mar 03 14:34:17 redacted_hostname iotedged[1249]: 2021-03-03T13:34:17Z [INFO] - Edge runtime is running. Mar 03 14:34:36 redacted_hostname iotedged[1249]: 2021-03-03T13:34:36Z [INFO] - Querying system resources... Mar 03 14:34:37 redacted_hostname iotedged[1249]: 2021-03-03T13:34:37Z [INFO] - [mgmt] - - - [2021-03-03 13:34:37.640691352 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 2536 "-" "-" auth_id(-) Mar 03 14:34:53 redacted_hostname iotedged[1249]: 2021-03-03T13:34:53Z [INFO] - [mgmt] - - - [2021-03-03 13:34:53.556695591 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 725 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:35:17 redacted_hostname iotedged[1249]: 2021-03-03T13:35:17Z [INFO] - Checking edge runtime status Mar 03 14:35:17 redacted_hostname iotedged[1249]: 2021-03-03T13:35:17Z [INFO] - Edge runtime is running. Mar 03 14:35:32 redacted_hostname iotedged[1249]: 2021-03-03T13:35:32Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-hub:1.0.10... Mar 03 14:35:58 redacted_hostname iotedged[1249]: 2021-03-03T13:35:58Z [INFO] - [mgmt] - - - [2021-03-03 13:35:58.389688938 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 725 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:36:17 redacted_hostname iotedged[1249]: 2021-03-03T13:36:17Z [INFO] - Checking edge runtime status Mar 03 14:36:17 redacted_hostname iotedged[1249]: 2021-03-03T13:36:17Z [INFO] - Edge runtime is running. Mar 03 14:36:59 redacted_hostname iotedged[1249]: 2021-03-03T13:36:59Z [INFO] - [mgmt] - - - [2021-03-03 13:36:59.551832423 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 725 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:37:13 redacted_hostname iotedged[1249]: 2021-03-03T13:37:13Z [INFO] - Pulling image redacted_registry.azurecr.io/ecsmanager:2.0.0-20210301080123PM-arm32v7... Mar 03 14:37:13 redacted_hostname iotedged[1249]: 2021-03-03T13:37:13Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-hub:1.0.10 Mar 03 14:37:13 redacted_hostname iotedged[1249]: 2021-03-03T13:37:13Z [INFO] - Creating module edgeHub... Mar 03 14:37:16 redacted_hostname iotedged[1249]: 2021-03-03T13:37:16Z [INFO] - Successfully created module edgeHub Mar 03 14:37:16 redacted_hostname iotedged[1249]: 2021-03-03T13:37:16Z [INFO] - [mgmt] - - - [2021-03-03 13:37:16.359865244 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1295 "-" "-" auth_id(-) Mar 03 14:37:17 redacted_hostname iotedged[1249]: 2021-03-03T13:37:17Z [INFO] - Checking edge runtime status Mar 03 14:37:17 redacted_hostname iotedged[1249]: 2021-03-03T13:37:17Z [INFO] - Edge runtime is running. Mar 03 14:37:26 redacted_hostname iotedged[1249]: 2021-03-03T13:37:26Z [INFO] - Successfully pulled image redacted_registry.azurecr.io/modbusmapper:2.0.0-20210301080123PM-arm32v7 Mar 03 14:37:26 redacted_hostname iotedged[1249]: 2021-03-03T13:37:26Z [INFO] - Creating module ModbusMapper... Mar 03 14:37:27 redacted_hostname iotedged[1249]: 2021-03-03T13:37:27Z [INFO] - Successfully created module ModbusMapper Mar 03 14:37:27 redacted_hostname iotedged[1249]: 2021-03-03T13:37:27Z [INFO] - [mgmt] - - - [2021-03-03 13:37:27.653397748 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1688 "-" "-" auth_id(-) Mar 03 14:38:00 redacted_hostname iotedged[1249]: 2021-03-03T13:38:00Z [INFO] - [mgmt] - - - [2021-03-03 13:38:00.321742123 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1540 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:38:17 redacted_hostname iotedged[1249]: 2021-03-03T13:38:17Z [INFO] - Checking edge runtime status Mar 03 14:38:17 redacted_hostname iotedged[1249]: 2021-03-03T13:38:17Z [INFO] - Edge runtime is running. Mar 03 14:38:53 redacted_hostname iotedged[1249]: 2021-03-03T13:38:53Z [INFO] - Pulling image redacted_registry.azurecr.io/fsmmanager:2.0.0-20210301080123PM-arm32v7... Mar 03 14:39:03 redacted_hostname iotedged[1249]: 2021-03-03T13:39:03Z [INFO] - [mgmt] - - - [2021-03-03 13:39:03.823087480 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1540 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:39:17 redacted_hostname iotedged[1249]: 2021-03-03T13:39:17Z [INFO] - Checking edge runtime status Mar 03 14:39:17 redacted_hostname iotedged[1249]: 2021-03-03T13:39:17Z [INFO] - Edge runtime is running. Mar 03 14:39:27 redacted_hostname iotedged[1249]: 2021-03-03T13:39:27Z [INFO] - Successfully pulled image redacted_registry.azurecr.io/ecsmanager:2.0.0-20210301080123PM-arm32v7 Mar 03 14:39:27 redacted_hostname iotedged[1249]: 2021-03-03T13:39:27Z [INFO] - Creating module ECSManager... Mar 03 14:39:28 redacted_hostname iotedged[1249]: 2021-03-03T13:39:28Z [INFO] - Successfully created module ECSManager Mar 03 14:39:28 redacted_hostname iotedged[1249]: 2021-03-03T13:39:28Z [INFO] - [mgmt] - - - [2021-03-03 13:39:28.672271941 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1736 "-" "-" auth_id(-) Mar 03 14:39:37 redacted_hostname iotedged[1249]: 2021-03-03T13:39:37Z [INFO] - Querying system resources... Mar 03 14:39:39 redacted_hostname iotedged[1249]: 2021-03-03T13:39:39Z [INFO] - [mgmt] - - - [2021-03-03 13:39:39.024144498 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 5173 "-" "-" auth_id(-) Mar 03 14:40:02 redacted_hostname iotedged[1249]: 2021-03-03T13:40:02Z [INFO] - [mgmt] - - - [2021-03-03 13:40:02.044827986 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1966 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:40:17 redacted_hostname iotedged[1249]: 2021-03-03T13:40:17Z [INFO] - Checking edge runtime status Mar 03 14:40:17 redacted_hostname iotedged[1249]: 2021-03-03T13:40:17Z [INFO] - Edge runtime is running. Mar 03 14:40:33 redacted_hostname iotedged[1249]: 2021-03-03T13:40:33Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge/modbus:1.0... Mar 03 14:41:11 redacted_hostname iotedged[1249]: 2021-03-03T13:41:11Z [INFO] - [mgmt] - - - [2021-03-03 13:41:11.043480979 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1966 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:41:11 redacted_hostname iotedged[1249]: 2021-03-03T13:41:11Z [INFO] - Successfully pulled image redacted_registry.azurecr.io/fsmmanager:2.0.0-20210301080123PM-arm32v7 Mar 03 14:41:11 redacted_hostname iotedged[1249]: 2021-03-03T13:41:11Z [INFO] - Creating module FsmManager... Mar 03 14:41:15 redacted_hostname iotedged[1249]: 2021-03-03T13:41:15Z [INFO] - Successfully created module FsmManager Mar 03 14:41:15 redacted_hostname iotedged[1249]: 2021-03-03T13:41:15Z [INFO] - [mgmt] - - - [2021-03-03 13:41:15.169822433 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 2590 "-" "-" auth_id(-) Mar 03 14:41:17 redacted_hostname iotedged[1249]: 2021-03-03T13:41:17Z [INFO] - Checking edge runtime status Mar 03 14:41:17 redacted_hostname iotedged[1249]: 2021-03-03T13:41:17Z [INFO] - Edge runtime is running. Mar 03 14:41:31 redacted_hostname iotedged[1249]: 2021-03-03T13:41:31Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge/modbus:1.0 Mar 03 14:41:31 redacted_hostname iotedged[1249]: 2021-03-03T13:41:31Z [INFO] - Creating module Modbus... Mar 03 14:41:34 redacted_hostname iotedged[1249]: 2021-03-03T13:41:34Z [INFO] - Successfully created module Modbus Mar 03 14:41:34 redacted_hostname iotedged[1249]: 2021-03-03T13:41:34Z [INFO] - [mgmt] - - - [2021-03-03 13:41:34.029419030 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1195 "-" "-" auth_id(-) Mar 03 14:41:34 redacted_hostname iotedged[1249]: 2021-03-03T13:41:34Z [INFO] - Starting module Modbus... Mar 03 14:41:35 redacted_hostname iotedged[1249]: 2021-03-03T13:41:35Z [INFO] - Successfully started module Modbus Mar 03 14:41:35 redacted_hostname iotedged[1249]: 2021-03-03T13:41:35Z [INFO] - [mgmt] - - - [2021-03-03 13:41:35.806731127 UTC] "POST /modules/Modbus/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:41:35 redacted_hostname iotedged[1249]: 2021-03-03T13:41:35Z [INFO] - Pulling image redacted_registry.azurecr.io/actuatormonitor:2.0.0-20210301080123PM-arm32v7... Mar 03 14:41:37 redacted_hostname iotedged[1249]: 2021-03-03T13:41:37Z [INFO] - [work] - - - [2021-03-03 13:41:37.324418447 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:42:17 redacted_hostname iotedged[1249]: 2021-03-03T13:42:17Z [INFO] - Checking edge runtime status Mar 03 14:42:17 redacted_hostname iotedged[1249]: 2021-03-03T13:42:17Z [INFO] - Edge runtime is running. Mar 03 14:42:26 redacted_hostname iotedged[1249]: 2021-03-03T13:42:26Z [INFO] - [mgmt] - - - [2021-03-03 13:42:26.326078586 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2826 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:43:16 redacted_hostname iotedged[1249]: 2021-03-03T13:43:16Z [INFO] - Pulling image redacted_registry.azurecr.io/average:2.0.0-20210301080123PM-arm32v7... Mar 03 14:43:17 redacted_hostname iotedged[1249]: 2021-03-03T13:43:17Z [INFO] - Checking edge runtime status Mar 03 14:43:17 redacted_hostname iotedged[1249]: 2021-03-03T13:43:17Z [INFO] - Edge runtime is running. Mar 03 14:43:31 redacted_hostname iotedged[1249]: 2021-03-03T13:43:31Z [INFO] - [mgmt] - - - [2021-03-03 13:43:31.119573041 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2826 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:43:45 redacted_hostname iotedged[1249]: 2021-03-03T13:43:45Z [INFO] - Successfully pulled image redacted_registry.azurecr.io/actuatormonitor:2.0.0-20210301080123PM-arm32v7 Mar 03 14:43:45 redacted_hostname iotedged[1249]: 2021-03-03T13:43:45Z [INFO] - Creating module ActuatorMonitor... Mar 03 14:43:47 redacted_hostname iotedged[1249]: 2021-03-03T13:43:47Z [INFO] - Successfully created module ActuatorMonitor Mar 03 14:43:47 redacted_hostname iotedged[1249]: 2021-03-03T13:43:47Z [INFO] - [mgmt] - - - [2021-03-03 13:43:47.101679127 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1755 "-" "-" auth_id(-) Mar 03 14:44:17 redacted_hostname iotedged[1249]: 2021-03-03T13:44:17Z [INFO] - Checking edge runtime status Mar 03 14:44:17 redacted_hostname iotedged[1249]: 2021-03-03T13:44:17Z [INFO] - Edge runtime is running. Mar 03 14:44:32 redacted_hostname iotedged[1249]: 2021-03-03T13:44:32Z [INFO] - [mgmt] - - - [2021-03-03 13:44:32.298988171 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 3262 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:44:39 redacted_hostname iotedged[1249]: 2021-03-03T13:44:39Z [INFO] - Querying system resources... Mar 03 14:44:42 redacted_hostname iotedged[1249]: 2021-03-03T13:44:42Z [INFO] - [mgmt] - - - [2021-03-03 13:44:42.208647863 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 9091 "-" "-" auth_id(-) Mar 03 14:44:56 redacted_hostname iotedged[1249]: 2021-03-03T13:44:56Z [INFO] - Pulling image mcr.microsoft.com/azure-blob-storage:latest... Mar 03 14:45:15 redacted_hostname iotedged[1249]: 2021-03-03T13:45:15Z [INFO] - Successfully pulled image redacted_registry.azurecr.io/average:2.0.0-20210301080123PM-arm32v7 Mar 03 14:45:15 redacted_hostname iotedged[1249]: 2021-03-03T13:45:15Z [INFO] - Creating module Average... Mar 03 14:45:17 redacted_hostname iotedged[1249]: 2021-03-03T13:45:17Z [INFO] - Checking edge runtime status Mar 03 14:45:19 redacted_hostname iotedged[1249]: 2021-03-03T13:45:19Z [INFO] - Edge runtime is running. Mar 03 14:45:19 redacted_hostname iotedged[1249]: 2021-03-03T13:45:19Z [INFO] - Successfully created module Average Mar 03 14:45:19 redacted_hostname iotedged[1249]: 2021-03-03T13:45:19Z [INFO] - [mgmt] - - - [2021-03-03 13:45:19.524246726 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1670 "-" "-" auth_id(-) Mar 03 14:45:43 redacted_hostname iotedged[1249]: 2021-03-03T13:45:43Z [INFO] - [mgmt] - - - [2021-03-03 13:45:43.389090197 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 3682 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:45:50 redacted_hostname iotedged[1249]: 2021-03-03T13:45:50Z [INFO] - Successfully pulled image mcr.microsoft.com/azure-blob-storage:latest Mar 03 14:45:50 redacted_hostname iotedged[1249]: 2021-03-03T13:45:50Z [INFO] - Creating module azureblobstorageoniotedge... Mar 03 14:45:52 redacted_hostname iotedged[1249]: 2021-03-03T13:45:52Z [INFO] - Successfully created module azureblobstorageoniotedge Mar 03 14:45:52 redacted_hostname iotedged[1249]: 2021-03-03T13:45:52Z [INFO] - [mgmt] - - - [2021-03-03 13:45:52.795919024 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1410 "-" "-" auth_id(-) Mar 03 14:45:52 redacted_hostname iotedged[1249]: 2021-03-03T13:45:52Z [INFO] - Starting module azureblobstorageoniotedge... Mar 03 14:45:54 redacted_hostname iotedged[1249]: 2021-03-03T13:45:54Z [INFO] - Successfully started module azureblobstorageoniotedge Mar 03 14:45:54 redacted_hostname iotedged[1249]: 2021-03-03T13:45:54Z [INFO] - [mgmt] - - - [2021-03-03 13:45:54.747087779 UTC] "POST /modules/azureblobstorageoniotedge/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:45:54 redacted_hostname iotedged[1249]: 2021-03-03T13:45:54Z [INFO] - Pulling image redacted_registry.azurecr.io/bluetooth:2.0.0-20210301080123PM-arm32v7... Mar 03 14:45:56 redacted_hostname iotedged[1249]: 2021-03-03T13:45:56Z [INFO] - [work] - - - [2021-03-03 13:45:56.026461437 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:46:17 redacted_hostname iotedged[1249]: 2021-03-03T13:46:17Z [INFO] - Checking edge runtime status Mar 03 14:46:17 redacted_hostname iotedged[1249]: 2021-03-03T13:46:17Z [INFO] - Edge runtime is running. Mar 03 14:46:49 redacted_hostname iotedged[1249]: 2021-03-03T13:46:49Z [INFO] - [mgmt] - - - [2021-03-03 13:46:49.693686868 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4902 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:47:17 redacted_hostname iotedged[1249]: 2021-03-03T13:47:17Z [INFO] - Checking edge runtime status Mar 03 14:47:17 redacted_hostname iotedged[1249]: 2021-03-03T13:47:17Z [INFO] - Edge runtime is running. Mar 03 14:47:35 redacted_hostname iotedged[1249]: 2021-03-03T13:47:35Z [INFO] - [work] - - - [2021-03-03 13:47:35.143992385 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 12989 "-" "-" auth_id(-) Mar 03 14:47:36 redacted_hostname iotedged[1249]: 2021-03-03T13:47:36Z [INFO] - [mgmt] - - - [2021-03-03 13:47:36.104328479 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4902 "-" "-" auth_id(-) Mar 03 14:47:38 redacted_hostname iotedged[1249]: 2021-03-03T13:47:38Z [INFO] - [mgmt] - - - [2021-03-03 13:47:38.802418882 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1550 "-" "-" auth_id(-) Mar 03 14:47:39 redacted_hostname iotedged[1249]: 2021-03-03T13:47:39Z [INFO] - [mgmt] - - - [2021-03-03 13:47:39.926288510 UTC] "PUT /identities/BlueTooth?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Mar 03 14:47:40 redacted_hostname iotedged[1249]: 2021-03-03T13:47:40Z [INFO] - Stopping module edgeHub... Mar 03 14:47:40 redacted_hostname iotedged[1249]: 2021-03-03T13:47:40Z [WARN] - Could not stop module edgeHub Mar 03 14:47:40 redacted_hostname iotedged[1249]: 2021-03-03T13:47:40Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:40 redacted_hostname iotedged[1249]: 2021-03-03T13:47:40Z [INFO] - [mgmt] - - - [2021-03-03 13:47:40.260984684 UTC] "POST /modules/edgeHub/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:40 redacted_hostname iotedged[1249]: 2021-03-03T13:47:40Z [INFO] - Starting module edgeHub... Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [INFO] - Successfully started module edgeHub Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [INFO] - [mgmt] - - - [2021-03-03 13:47:47.332462516 UTC] "POST /modules/edgeHub/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [INFO] - Stopping module FsmManager... Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [WARN] - Could not stop module FsmManager Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [INFO] - [mgmt] - - - [2021-03-03 13:47:47.360173923 UTC] "POST /modules/FsmManager/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:47 redacted_hostname iotedged[1249]: 2021-03-03T13:47:47Z [INFO] - Starting module FsmManager... Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [INFO] - Successfully started module FsmManager Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [INFO] - [mgmt] - - - [2021-03-03 13:47:48.657747346 UTC] "POST /modules/FsmManager/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [INFO] - Stopping module ActuatorMonitor... Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [WARN] - Could not stop module ActuatorMonitor Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [INFO] - [mgmt] - - - [2021-03-03 13:47:48.677838043 UTC] "POST /modules/ActuatorMonitor/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:48 redacted_hostname iotedged[1249]: 2021-03-03T13:47:48Z [INFO] - Starting module ActuatorMonitor... Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - Successfully started module ActuatorMonitor Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - [mgmt] - - - [2021-03-03 13:47:51.377738262 UTC] "POST /modules/ActuatorMonitor/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - [mgmt] - - - [2021-03-03 13:47:51.382944984 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5052 "-" "iotedge/0.1.0" auth_id(-) Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - Stopping module ModbusMapper... Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [WARN] - Could not stop module ModbusMapper Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - [mgmt] - - - [2021-03-03 13:47:51.395978196 UTC] "POST /modules/ModbusMapper/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:51 redacted_hostname iotedged[1249]: 2021-03-03T13:47:51Z [INFO] - Starting module ModbusMapper... Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - Successfully started module ModbusMapper Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - [mgmt] - - - [2021-03-03 13:47:55.607997116 UTC] "POST /modules/ModbusMapper/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - Stopping module Modbus... Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [WARN] - Could not stop module Modbus Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - [mgmt] - - - [2021-03-03 13:47:55.699091788 UTC] "POST /modules/Modbus/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - [work] - - - [2021-03-03 13:47:55.700960156 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/certificate/server?api-version=2019-01-30 HTTP/1.1" 201 Created 9278 "-" "-" auth_id(-) Mar 03 14:47:55 redacted_hostname iotedged[1249]: 2021-03-03T13:47:55Z [INFO] - Starting module Modbus... Mar 03 14:47:56 redacted_hostname iotedged[1249]: 2021-03-03T13:47:56Z [INFO] - [work] - - - [2021-03-03 13:47:56.827662054 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:47:58 redacted_hostname iotedged[1249]: 2021-03-03T13:47:58Z [INFO] - [work] - - - [2021-03-03 13:47:58.812332955 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [INFO] - Successfully started module Modbus Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [INFO] - [mgmt] - - - [2021-03-03 13:47:59.084619120 UTC] "POST /modules/Modbus/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [INFO] - Stopping module Average... Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [WARN] - Could not stop module Average Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [WARN] - caused by: Target of operation already in this state Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [INFO] - [mgmt] - - - [2021-03-03 13:47:59.176522848 UTC] "POST /modules/Average/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Mar 03 14:47:59 redacted_hostname iotedged[1249]: 2021-03-03T13:47:59Z [INFO] - Starting module Average... Mar 03 14:48:01 redacted_hostname iotedged[1249]: 2021-03-03T13:48:01Z [INFO] - [work] - - - [2021-03-03 13:48:01.214308906 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:48:02 redacted_hostname iotedged[1249]: 2021-03-03T13:48:02Z [INFO] - [work] - - - [2021-03-03 13:48:02.132477306 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:48:02 redacted_hostname iotedged[1249]: 2021-03-03T13:48:02Z [INFO] - Successfully started module Average Mar 03 14:48:02 redacted_hostname iotedged[1249]: 2021-03-03T13:48:02Z [INFO] - [mgmt] - - - [2021-03-03 13:48:02.540782266 UTC] "POST /modules/Average/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Mar 03 14:48:02 redacted_hostname iotedged[1249]: 2021-03-03T13:48:02Z [INFO] - [work] - - - [2021-03-03 13:48:02.838396482 UTC] "POST /modules/%24edgeAgent/genid/637431235995678909/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 12989 "-" "-" auth_id(-) Mar 03 14:48:03 redacted_hostname iotedged[1249]: 2021-03-03T13:48:03Z [INFO] - [work] - - - [2021-03-03 13:48:03.791308005 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:48:07 redacted_hostname iotedged[1249]: 2021-03-03T13:48:07Z [INFO] - [work] - - - [2021-03-03 13:48:07.161373390 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Mar 03 14:48:08 redacted_hostname iotedged[1249]: 2021-03-03T13:48:08Z [INFO] - [mgmt] - - - [2021-03-03 13:48:08.478490003 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5152 "-" "-" auth_id(-) Mar 03 14:48:09 redacted_hostname iotedged[1249]: 2021-03-03T13:48:09Z [INFO] - [mgmt] - - - [2021-03-03 13:48:09.324240879 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1550 "-" "-" auth_id(-) Mar 03 14:48:10 redacted_hostname iotedged[1249]: 2021-03-03T13:48:10Z [INFO] - [mgmt] - - - [2021-03-03 13:48:10.443034704 UTC] "PUT /identities/BlueTooth?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Mar 03 14:48:10 redacted_hostname iotedged[1249]: 2021-03-03T13:48:10Z [INFO] - Pulling image redacted_registry.azurecr.io/bluetooth:2.0.0-20210301080123PM-arm32v7... Mar 03 14:48:10 redacted_hostname iotedged[1249]: 2021-03-03T13:48:10Z [INFO] - [work] - - - [2021-03-03 13:48:10.996239540 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/sign?api-version=2019-01-30 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Mar 03 14:48:13 redacted_hostname iotedged[1249]: 2021-03-03T13:48:13Z [INFO] - [work] - - - [2021-03-03 13:48:13.327719580 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 393 "-" "-" auth_id(-) Mar 03 14:48:13 redacted_hostname iotedged[1249]: 2021-03-03T13:48:13Z [INFO] - [work] - - - [2021-03-03 13:48:13.822951626 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 368 "-" "-" auth_id(-) Mar 03 14:48:14 redacted_hostname iotedged[1249]: 2021-03-03T13:48:14Z [INFO] - [work] - - - [2021-03-03 13:48:14.010236566 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 573 "-" "-" auth_id(-) Mar 03 14:48:14 redacted_hostname iotedged[1249]: 2021-03-03T13:48:14Z [INFO] - [work] - - - [2021-03-03 13:48:14.207497143 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 552 "-" "-" auth_id(-) Mar 03 14:48:14 redacted_hostname iotedged[1249]: 2021-03-03T13:48:14Z [INFO] - [work] - - - [2021-03-03 13:48:14.733159380 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 621 "-" "-" auth_id(-) Mar 03 14:48:14 redacted_hostname iotedged[1249]: 2021-03-03T13:48:14Z [INFO] - [work] - - - [2021-03-03 13:48:14.888842684 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 637 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.223131218 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 629 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.230613389 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/sign?api-version=2019-01-30 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.377904531 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 625 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.512231679 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 641 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.671819740 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 625 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.785476036 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 649 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.894911330 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 645 "-" "-" auth_id(-) Mar 03 14:48:15 redacted_hostname iotedged[1249]: 2021-03-03T13:48:15Z [INFO] - [work] - - - [2021-03-03 13:48:15.996649038 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 641 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.102504730 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 637 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.199771334 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 477 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.296683411 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 641 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.399385069 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 641 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.530007668 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 633 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.630394036 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 552 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.663294670 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 673 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.829973135 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 552 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.859884683 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 552 "-" "-" auth_id(-) Mar 03 14:48:16 redacted_hostname iotedged[1249]: 2021-03-03T13:48:16Z [INFO] - [work] - - - [2021-03-03 13:48:16.904705884 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 637 "-" "-" auth_id(-) Mar 03 14:48:17 redacted_hostname iotedged[1249]: 2021-03-03T13:48:17Z [INFO] - [work] - - - [2021-03-03 13:48:17.527845773 UTC] "POST /modules/%24edgeHub/genid/637431235995678909/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 552 "-" "-" auth_id(-) Mar 03 14:48:17 redacted_hostname iotedged[1249]: 2021-03-03T13:48:17Z [INFO] - Checking edge runtime status Mar 03 14:48:17 redacted_hostname iotedged[1249]: 2021-03-03T13:48:17Z [INFO] - Edge runtime is running. ```

More detailed or specific logs can be provided if needed.

Additional Information

Additional Software

Our devices also run the following services:

Experiments

We have tried multiple ideas to identify the root cause of the memory leak, and try to fix it, but with no luck so far. All the following graphs come from the data collected by the Telegraf agent, visualized on Azure Metrics.

Control experiment

With all the services enabled, and working as planned in production, we get the following memory behavior:

control

Impact of rsyslog

Disabling rsyslog does not change the memory behavior:

rsyslog

Impact of our IoT Edge modules

Disabling all of our custom IoT Edge modules reduces the memory usage increase, but does not remove it completely.

modules

Impact of Telegraf

Greatly increasing the workload of Telegraf (by increasing the amount of metrics to report tenfold) leads to an erratic memory behavior. It initially seems that the memory leak is gone, but it reappears after a dozen hours, hinting that the memory usage of Telegraf was only hiding the memory leak in noise.

telegraf

Impact of IoT Edge

Disabling IoT Edge entirely (with systemctl disable iotedge followed by a reboot) reduces the memory leak to less than 5Mo/day.

iotedge

Impact of Docker container memory limits

Up until this points, all of the IoT Edge modules/Docker containers have been running with full access to the 1GB of RAM of the device. Limiting this memory to 26Mo per custom module, 58Mo for edgeAgent, and 137Mo for edgeHub still results in a memory leak, but this time accompanied with frequent crashes/reboots of edgeHub.

docker_memory

Impact of a swap file

Adding a 512Mo swapfile to our device initially helps alleviate the memory leak, but this effect stops after about 12 hours.

swapfile

Impact of the .NET Garbage Collection

According to the information found in this .NET issue and this blog post, the default .NET garbage collector is not always perfectly adapted to memory-constrained environments. A potential fix is to change it, by adding the following in the .csproj of each module:

<PropertyGroup>
    <ServerGarbageCollection>false</ServerGarbageCollection>
</PropertyGroup>

This did not have any effect on the memory consumption.

gc

Impact of the .NET Core version

All of our modules are built on top of .NET 2.1 LTS. This Microsoft blog post claims that .NET Core 3.0 (and beyond) is more suited to resource-constrained environments, such as an embedded device running multiple Docker containers. To test this, we upgraded all of our modules to .NET 3.1. This did not have any effect on the memory usage.

dotnet_version

Impact of limited system memory

To confirm that the two previous tests did indeed cause issues when the system memory ran out, we artificially reduced the system memory of our devices to 650MB (out of 1GB available). This is done with the total_mem=650 configuration option in /boot/config.txt (see this link for reference). This did not change the memory consumption of the devices, and only caused them to become unresponsive after less than 24 hours of uptime.

Garbage Collector: memory_gc

.NET 3.1: memory_dotnet_version

and-rewsmith commented 3 years ago

My interpretation of these graphs is that edge is causing the memory usage to grow. With respect to the custom modules:

The memory seems to be growing in your control case, and the growth seems prevalent even with no custom modules (although they exacerbate the problem). Is this a leak though? My understanding memory might not be freed until triggered by garbage collection. Although I would guess garbage collection should trigger if you start to run out of memory and you will see the memory usage go down. So in that sense it is looking like some memory issue since it is not freed when the memory starts running out.

However in my experience, both on arm32 and amd64, I usually see more of a saw tooth pattern shown in the picture I attached. This is an amd64 edge device running 1.0.10 that has been up and running since September. We have alerts tied to this machine for memory usage, so I would be surprised if we really had a severe leak. Therefore it is likely you can fix your issue just by reducing the load on your pi. If you would like to verify this you can run iotedge without the custom modules and hopefully you will observe that memory does not grow indefinitely, but is cleaned up in this saw tooth pattern.

You said EdgeHub was crashing. I assume this is due to OOM. I would try to give it more resources until this stops happening. Then, based on the remaining system resources you can determine how you want to change your custom workload requirements. EdgeResourceConsumption

and-rewsmith commented 3 years ago

Also, I am curious as to the exact behavior when EdgeHub fails. Do you have those logs?

AdrienCos commented 3 years ago

Ok, we will start the following tests as soon as possible to confirm your hypothesis:

I will post the results here when they arrive.

Regarding the logs of edgeHub, I don't have them on hand, as the logs on our devices got rotated before I had a chance to grab them. I will post them here if I manage to get them.

emilm commented 3 years ago

@AdrienCos did you get any results? :) Have similar problems with linear decrease of available memory. Using iotedge 1.0.10.3 (fca5cb4b7971992465f5786c16819d9f3535d3c9)

JardarM commented 3 years ago

With regards to memory consumption of the edgeHub and edgeAgent, what is expected consumption? Right now the docker containers for edgeHub consumes 155MB and edgeAgent consumes 95MB. And what parameters will impacts its consumption? To what extent will protocol use impact this (AMQP/MQTT)?

AdrienCos commented 3 years ago

Sorry for the long delay, here is an update on the tests I ran.

As explained in my last message, I ran the two devices with the exact same minimal IoT Edge deployment, one of them having only 400MB of RAM available. The test ran between March 15th and April 1st. Here is attached the graph of memory use over this time period, with the RAM-limited device in blue, and the other one in red.

NB: The drop on April 1st was caused by a power outage in our labs, with rebooted the devices, not by the GC.

The data is collected with a Telegraf agent running on the device, and reporting various health-related metrics every minute to Azure Monitor.

image

After 2 days of memory increase, the memory-limited device stopped sending data to Azure, and became unreachable over SSH. No amount of waiting managed to fix this.

The regular device stayed online for the 15 days. During this period, its memory use increased from 260MB to 460MB, with no sign of memory being freed.

These tests seem to have been inconclusive. Until we can find something else to try, I will leave the test running to see if a different behavior appears this time.

emilm commented 3 years ago

Thanks @AdrienCos ! We have the exact same problem! Why is edgeHub using the memory for btw? I managed to log in and restart edgeHub, and the memory consumption went like this (Available memory metric in one of our containers): image All this was with AMPQS . Changed to MQTT on our 2 containers using IOT Hub:

image mcr.microsoft.com/azureiotedge-hub:1.0.10.3-linux-arm32v7 : edgeHub env settings: OptimizeForPerformance = false httpSettings__enabled = false

and-rewsmith commented 3 years ago

@emilm EdgeHub manages a lot of internal state to track device connections, track connectivity status, manage protocol heads, persist messages, etc. When you say you have the same problem, are you referring to seeing failures in EdgeHub you think are related to its memory usage?

When EdgeHub is in a busy test environment where lots of events are passing through the system we typically see this usage:

@AdrienCos The fact that this memory limited device has become responsive is very concerning. It would give us more info to see the memory usage for individual containers, so I am doing my own tests and will update you.

I forgot to mention this last time, but are you running with the OptimizeForPerformance EdgeHub environment variable set to false? It is not recommended to let this default to true on arm as it causes larger memory allocations. https://docs.microsoft.com/en-us/azure/iot-edge/production-checklist?view=iotedge-2018-06#reduce-memory-space-used-by-iot-edge-hub

One thing I want to bring up is the behavior of garbage collection. It is not expected to run periodically, but only under the conditions explained in this link. Therefore it is sometimes acceptable to see increases over some time. However I am very concerned by EdgeHub becoming unresponsive when it is only the system modules running. If you are currently running with this set to true, can you try toggling it to false for your tests? https://docs.microsoft.com/en-us/dotnet/standard/garbage-collection/fundamentals#conditions-for-a-garbage-collection

emilm commented 3 years ago

@emilm EdgeHub manages a lot of internal state to track device connections, track connectivity status, manage protocol heads, persist messages, etc. When you say you have the same problem, are you referring to seeing failures in EdgeHub you think are related to its memory usage?

Thanks for responding, @and-rewsmith ! I won't blame it on iot edge, because I don't know for sure. But I ran an older version of iot edge (although our software has changed as well) does not have this problem. I just see a steady, linear decrease of the "available memory" metric.

Last 48 hours: image

Snapshot of mem usage right now (end of that graph) ps aux --sort -rss | head USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND 1000 22233 0.2 17.2 480488 172584 ? Ssl Apr07 5:20 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Hub.Service.dll 1000 21936 1.8 9.9 319372 99128 ? Ssl Apr07 42:31 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Agent.Service.dll root 24401 1.1 9.2 358544 92152 ? Ssl Apr07 27:02 <redacted, our app> root 24663 0.0 7.8 312576 78368 ? Ssl Apr07 1:42 <redacted, our app> root 21609 2.0 6.5 953356 65260 ? Ssl Apr07 47:28 /usr/bin/dockerd -H fd:// --experimental --log-driver=journald root 21618 0.7 3.3 962152 33720 ? Ssl Apr07 16:57 containerd --config /var/run/docker/containerd/containerd.toml --log-level info root 21816 0.4 2.0 56220 20636 ? Ssl Apr07 11:14 /usr/bin/iotedged -c /config.yaml root 274 0.1 1.3 933904 13496 ? Ssl Mar19 57:11 /usr/bin/mender daemon root 22217 0.0 0.7 881160 7964 ? Sl Apr07 1:21 containerd-shim -namespace moby -workdir /var/lib/docke...`

free -m total used free shared buff/cache available Mem: 975 477 33 14 463 466 Swap: 0 0 0

Microsoft.Azure.Devices.Edge.Hub.Service.dll was 15% usage yesterday, and I should have taken notes of the rest as I do now. Please let me know if you need more information about process memory usage! Is there an easy way to use dotnet-gcdump on hub and agent (I don't have package manager or dotnet stuff in the host OS)?

Update:

USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND 1000 22233 0.2 17.4 482536 173940 ? Ssl Apr07 6:15 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Hub.Service.dll 1000 21936 1.8 9.8 319372 98820 ? Ssl Apr07 52:24 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Agent.Service.dll root 24401 1.1 9.2 358864 91976 ? Ssl Apr07 33:17 /usr/lib/jvm/bin/java --add-opens java.base/java.lang=ALL-UNNAMED <redacted, our app> root 24663 0.0 7.8 312560 78332 ? Ssl Apr07 1:58 dotnet <redacted, our app> root 21609 2.0 6.5 953356 65264 ? Ssl Apr07 58:41 /usr/bin/dockerd -H fd:// --experimental --log-driver=journald root 21618 0.7 3.3 962152 33736 ? Ssl Apr07 20:59 containerd --config /var/run/docker/containerd/containerd.toml --log-level info root 21816 0.4 2.1 58268 21956 ? Ssl Apr07 13:54 /usr/bin/iotedged -c root 274 0.1 1.3 933904 13500 ? Ssl Mar19 57:57 /usr/bin/mender daemon root 22217 0.0 0.7 881160 7976 ? Sl Apr07 1:40 containerd-shim -namespace moby -workdir /var/lib/docker/containe...

free -m total used free shared buff/cache available Mem: 975 483 24 14 467 460 Swap: 0 0 0

Hub has increased but only 0.2% in 9 hours. Seems like memory usage (temporarily) has flattened out. But I will keep an eye on it.

I switched to MQTT from AMQPS before starting this post.

New snapshot Fri Apr 9 18:55:19 UTC 2021 USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND 1000 22233 0.2 17.6 483672 176392 ? Ssl Apr07 7:19 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Hub.Service.dll 1000 21936 1.8 9.8 319372 98204 ? Ssl Apr07 63:50 /usr/bin/dotnet Microsoft.Azure.Devices.Edge.Agent.Service.dll root 24401 1.1 9.2 359184 92012 ? Ssl Apr07 40:31 /usr/lib/jvm/bin/java <redacted, our app> root 24663 0.0 7.8 312512 78208 ? Ssl Apr07 2:17 dotnet <redacted, our app> root 21609 2.0 6.5 953356 65276 ? Ssl Apr07 71:38 /usr/bin/dockerd -H fd:// --experimental --log-driver=journald root 21618 0.7 3.3 962152 33664 ? Ssl Apr07 25:38 containerd --config /var/run/docker/containerd/containerd.toml --log-level info root 21816 0.4 2.1 59744 21884 ? Ssl Apr07 16:59 /usr/bin/iotedged -c root 274 0.1 1.2 933904 12276 ? Ssl Mar19 58:50 /usr/bin/mender daemon root 22217 0.0 0.8 881160 7996 ? Sl Apr07 2:01 containerd-shim -namespace moby -workdir /var/lib/docker/containerd/daemon/io.container free -m total used free shared buff/cache available Mem: 975 492 38 14 443 450 Swap: 0 0 0

JardarM commented 3 years ago

Based on our research so far it seems it might be related to use of the AMQP. I see that there is a new version of the client library for java and that this issues was addressed at least two times. https://github.com/Azure/azure-iot-sdk-java/releases/tag/2021-03-12

Event though we do not see an increase in the client (java process), could it be that this affects the edgeHub?

and-rewsmith commented 3 years ago

Hey @AdrienCos, @emilm, @JardarM I wanted to provide an update. First off, I don't think the referenced java devices sdk release indicates any issue in EdgeHub, as we use the C# Devices SDK.

I ran the tests on a Rbpi 4 with 1 GB ram and iotedge version 1.1. In this test I did see the memory usage for EdgeHub steadily increase over a multi day period. My theory was that this was because garbage collection wasn't triggered and adding memory load to the device would curb EdgeHub's usage. I tested this theory by running the following command:

stress --vm 4 --vm-bytes 75M --vm-hang 0

Running this command leaves ~90MB of available memory on the pi. When I ran this I immediately saw the EdgeHub container memory usage decrease. It also did not increase over the next 4 hours like it did before the system became memory-constrained. I will keep monitoring this on the pi, but so far it is behaving like I would expect. arm-test

In retrospect I would have done this test with docker create options to limit the memory usage of the EdgeHub container more strictly, but I think this works just as well.

For more context, we recently released version 1.2 of iotedge and here is the memory usage pattern we saw over a multi-day busy test. Notice how the edgehub memory usage increases over time, but when the system becomes memory constrained garbage collection runs and frees memory. Maybe there is something specific to the behavior on a pi, so I will leave my arm test running and update as soon as I see concerning behavior. 1 2-testing

emilm commented 3 years ago

Thanks for your report @and-rewsmith! What about 1.0.10.3 (fca5cb4) and RPI3 / RPI3+? Did you run 64 bit OS? That's what @AdrienCos and we run.

AdrienCos commented 3 years ago

Hum, that's interesting. Memory being freed when the system is under stress did not happen in our testing. The only thing it accomplished was rendering the device unreachable, and causing it to stop reporting data to Azure Monitor.

BTW, we run a 32-bit OS, not a 64-bit.

and-rewsmith commented 3 years ago

@emilm I am testing 1.1 as it is our LTS release. I am also testing on a RPi4 as it is all I have available right now. It is running raspbian so it is a 32 bit OS. I recommend upgrading from 1.0.10 to 1.1 so that you get the servicing updates.

@AdrienCos I went to check on this last night and found the device unresponsive to ssh and that metrics had stopped being uploaded! It was quite concerning so I setup another test where I use docker createOptions to strictly limit the EdgeHub memory to 105MB.

This test seems to be doing much better. aww-board (3)

I have put numbers on the chart where I want to recap for clarity:

  1. My initial test where EdgeHub was running memory unconstrained. It had a large initial increase in memory consumption that showed it would continue.
  2. I applied memory constraints to the device and noticed the memory consumption go down and stay steady for a few hours, but eventually the system became unresponsive and we don't have metrics. Therefore we cannot trust this straight line in the box here, as it should be a dashed line indicating no data.
  3. My new test with docker create options strictly limiting the memory usage of EdgeHub. This seems to not show the same consumption pattern as 1. Also it does not consume as much memory as EdgeHub did in 2. It seems to be maintaining a level use of memory so far and there are no errors in the logs.

There are two cases now:

Assuming my createOptions test continues to work like expected, I would recommend applying your own memory constraints onto EdgeHub (and maybe other dotnet modules). Doing this would carve out a chunk of memory for system resources that will hopefully prevent this problem. I'd also recommend following this guide and turning off any protocol heads you aren't using: https://docs.microsoft.com/en-us/azure/iot-edge/production-checklist?view=iotedge-2020-11#reduce-memory-space-used-by-iot-edge-hub

I will keep updating on the results.

emilm commented 3 years ago

@and-rewsmith Thanks! it's a shame https://github.com/Azure/meta-iotedge has been become inactive though.

What are the appropriate memory constraint settings in AMQPS for Hub ? And should there be settings on Agent? Is there any danger in running 1.1 containers on 1.0.10.3 iotedged? arm32v7, 1GB RAM

Thanks!

and-rewsmith commented 3 years ago

@emilm

What are the appropriate memory constraint settings in AMQPS for Hub ?

I think the main concern is that enough memory is left available for the system resources. My intuition is that around 200-300MB is enough for EdgeHub to handle a busy environment.

And should there be settings on Agent?

I know that when uploading logs a lot of memory can be used, so I would set this too. Otherwise Edge Agent seems to be less of a risk. I would err on the side of caution and limit it anyway. My intution is ~100MB. Maybe more if you have log upload issues.

Is there any danger in running 1.1 containers on 1.0.10.3 iotedged?

We don't test for compatibility between service and system modules. I think you would want to upgrade both the service and the system modules.

emilm commented 3 years ago

@and-rewsmith Thanks again! Good with some numbers! I am also upgrading to 1.1 . As a general question, will there be a mode that could operate even more constrained? For embedded devices. I mean there would be little left for actual software when the part that is responsible for sending and receiving messages to the cloud + edgeAgent takes up 350+ MB of the RAM. Imagine a Pi Zero for example with additional containers

and-rewsmith commented 3 years ago

@emilm As far as I know, the optimizeForPerformance EdgeHub env var set to false is the only thing I know of to optimize for a low resource environment.

That 350MB recommendation for system modules was for a busy environment where you also needed to upload a lot of logs. In one of our test suites we have run with ~15 custom modules on arm all sending telemetry to EdgeHub every few seconds. In this setup EdgeHub is doing most of the compute whereas the custom modules are just generating/sending dummy telemetry. If your workload compute is oriented more towards your custom modules and less telemetry flowing towards EdgeHub, I would think you can decrease the memory cap on EdgeHub.

If after tuning you cannot achieve your desired workload, I would recommend considering an embedded device with more resources.

Another thing to note is that the edge device is designed to be a gateway to the cloud such that off-device compute is possible. If your workload requirements exceed the remaining memory constraints of the pi, you can offload this compute to another device.

and-rewsmith commented 3 years ago

@AdrienCos Everything is still looking good in the test where I strictly limit EdgeHub memory usage via docker createOptions. So it is looking like the second case outlined above. strict-limit-4-14

AdrienCos commented 3 years ago

@and-rewsmith Alright, I'll try this on one of out test devices. Could you send me the deployment file you used on the device that produced this graph? I'll put some memory limits on edgeHub, and leave all the other modules unconstrained, and observe the resulting behavior.

emilm commented 3 years ago

https://docs.microsoft.com/en-us/azure/iot-edge/how-to-use-create-options?view=iotedge-2020-11#restrict-module-memory-and-cpu-usage

Do you use "Memory" and "MemorySwap" or just "Memory"?

and-rewsmith commented 3 years ago

@emilm I am using just Memory.

@AdrienCos I can't attach the deployment file as the file type is json I pasted it below and stripped the credentials.

{
    "modulesContent": {
        "$edgeAgent": {
            "properties.desired": {
                "modules": {},
                "runtime": {
                    "settings": {
                        "minDockerVersion": "v1.25",
                        "registryCredentials": {}
                    },
                    "type": "docker"
                },
                "schemaVersion": "1.0",
                "systemModules": {
                    "edgeAgent": {
                        "settings": {
                            "image": "mcr.microsoft.com/azureiotedge-agent:1.1.0-linux-arm32v7",
                            "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"125\",\"compress\":\"true\"}}, \"PortBindings\": {\"9600/tcp\": [{\"HostPort\": \"9600\"}]}}}"
                        },
                        "type": "docker"
                    },
                    "edgeHub": {
                        "settings": {
                            "image": "mcr.microsoft.com/azureiotedge-hub:1.1.0-linux-arm32v7",
                            "createOptions": "{\"ExposedPorts\": {\"9600/tcp\": {}}, \"HostConfig\": {\"Memory\":105000000, \"LogConfig\":{\"Type\":\"json-file\",\"Config\":{\"max-size\":\"4m\",\"max-file\":\"125\",\"compress\":\"true\"}}, \"PortBindings\": {\"8883/tcp\": [{\"HostPort\": \"8883\"}],\"5671/tcp\": [{\"HostPort\": \"5671\"}],\"9600/tcp\": [{\"HostPort\": \"9601\"}]}}}"
                        },
                        "type": "docker",
                        "env": {
                            "OptimizeForPerformance": {
                                "value": "false"
                            }
                        },
                        "status": "running",
                        "restartPolicy": "always"
                    }
                }
            }
        },
        "$edgeHub": {
            "properties.desired": {
                "routes": {
                    "TempSensorToTempFilter": "FROM /messages/modules/* INTO $upstream"
                },
                "schemaVersion": "1.0",
                "storeAndForwardConfiguration": {
                    "timeToLiveSecs": 86400
                }
            }
        }
    }
}
AdrienCos commented 3 years ago

@and-rewsmith Thanks for that, I'll start a couple of tests with different number of custom modules to evaluate how well the Memory option works.

AdrienCos commented 3 years ago

After leaving a first test run overnight, I have noticed some issue with the edgeHub module (and maybe with IoT Edge as a whole, I'm not sure). Here is the graph of the memory use for a device with all 8 of our custom modules (as well as edgeHub and edgeAgent), with edgeHub being limited to 300MB of RAM:

image

Starting at 8am (UTC+2), the memory use drops significantly every 30 minutes. It seems that the entire IoT Edge runtime restarts. I am attaching the iotedge logs here, in the case that it helps understand what is happening.

Log of a periodic large memory use drop ``` Apr 20 11:29:59 device-hostname iotedged[18227]: 2021-04-20T09:29:59Z [INFO] - [mgmt] - - - [2021-04-20 09:29:59.585274422 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 9256 "-" "-" auth_id(-) Apr 20 11:30:01 device-hostname systemd[1]: Stopping Azure IoT Edge daemon... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Received SIGTERM, starting shutdown Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping edge runtime module edgeAgent Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module edgeAgent... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - [mgmt] - - - [2021-04-20 09:30:01.615141049 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 9256 "-" "-" auth_id(-) Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_7... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_1... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module edgeHub... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_3... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_4... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_2... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_8... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_5... Apr 20 11:30:01 device-hostname iotedged[18227]: 2021-04-20T09:30:01Z [INFO] - Stopping module custom_module_6... Apr 20 11:30:04 device-hostname iotedged[18227]: 2021-04-20T09:30:04Z [INFO] - Successfully stopped module custom_module_8 Apr 20 11:30:04 device-hostname iotedged[18227]: 2021-04-20T09:30:04Z [INFO] - [mgmt] - - - [2021-04-20 09:30:04.529176488 UTC] "POST /modules/custom_module_8/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:04 device-hostname iotedged[18227]: 2021-04-20T09:30:04Z [INFO] - Successfully stopped module custom_module_1 Apr 20 11:30:04 device-hostname iotedged[18227]: 2021-04-20T09:30:04Z [INFO] - [mgmt] - - - [2021-04-20 09:30:04.881227644 UTC] "POST /modules/custom_module_1/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:07 device-hostname iotedged[18227]: 2021-04-20T09:30:07Z [INFO] - Successfully stopped module custom_module_2 Apr 20 11:30:07 device-hostname iotedged[18227]: 2021-04-20T09:30:07Z [INFO] - [mgmt] - - - [2021-04-20 09:30:07.030231229 UTC] "POST /modules/custom_module_2/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - Successfully stopped module custom_module_3 Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - [mgmt] - - - [2021-04-20 09:30:12.401215041 UTC] "POST /modules/custom_module_3/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - Successfully stopped module custom_module_4 Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - [mgmt] - - - [2021-04-20 09:30:12.595892069 UTC] "POST /modules/custom_module_4/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - Successfully stopped module custom_module_5 Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - [mgmt] - - - [2021-04-20 09:30:12.668742303 UTC] "POST /modules/custom_module_5/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - Successfully stopped module custom_module_6 Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - [mgmt] - - - [2021-04-20 09:30:12.691874884 UTC] "POST /modules/custom_module_6/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - Successfully stopped module custom_module_7 Apr 20 11:30:12 device-hostname iotedged[18227]: 2021-04-20T09:30:12Z [INFO] - [mgmt] - - - [2021-04-20 09:30:12.697781480 UTC] "POST /modules/custom_module_7/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:14 device-hostname iotedged[18227]: 2021-04-20T09:30:14Z [INFO] - Successfully stopped module edgeHub Apr 20 11:30:14 device-hostname iotedged[18227]: 2021-04-20T09:30:14Z [INFO] - [mgmt] - - - [2021-04-20 09:30:14.303036820 UTC] "POST /modules/edgeHub/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:30:16Z [INFO] - Successfully stopped module edgeAgent Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:30:16Z [INFO] - Edge runtime will stop because of the shutdown signal. Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:30:16Z [INFO] - Shutdown complete. Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:00:14Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:01:45Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:01:45Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:01:45Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:03:03Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:03:03Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:03:58Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:03:58Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:06:16Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:06:16Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:08:43Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:08:43Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:12:23Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:12:23Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:18:18Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHubAlias Apr 20 11:30:16 device-hostname iotedged[18227]: 2021-04-20T09:18:18Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048 Apr 20 11:30:16 device-hostname systemd[1]: iotedge.service: Succeeded. Apr 20 11:30:16 device-hostname systemd[1]: Stopped Azure IoT Edge daemon. Apr 20 11:30:16 device-hostname systemd[1]: Starting Azure IoT Edge daemon... Apr 20 11:30:16 device-hostname systemd[1]: Started Azure IoT Edge daemon. Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Starting Azure IoT Edge Security Daemon Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Version - 1.0.10 Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Using config file: /etc/iotedge/config.yaml Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Configuring /var/lib/iotedge as the home directory. Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Configuring certificates... Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Transparent gateway certificates not found, operating in quick start mode... Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Finished configuring provisioning environment variables and certificates. Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Initializing hsm... Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Finished initializing hsm. Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Provisioning edge device... Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Starting provisioning edge device via TPM... Apr 20 11:30:16 device-hostname iotedged[3865]: 2021-04-20T09:30:16Z [INFO] - Starting DPS registration with scope_id "0ne0006D167", registration_id "device-registration-id" Apr 20 11:30:30 device-hostname iotedged[3865]: 2021-04-20T09:30:30Z [INFO] - DPS registration assigned device "device-id" in hub "iot-hub-address" Apr 20 11:30:30 device-hostname iotedged[3865]: 2021-04-20T09:30:30Z [INFO] - Finished provisioning edge device. Apr 20 11:30:30 device-hostname iotedged[3865]: 2021-04-20T09:30:30Z [INFO] - Initializing the module runtime... Apr 20 11:30:30 device-hostname iotedged[3865]: 2021-04-20T09:30:30Z [INFO] - Initializing module runtime... Apr 20 11:30:30 device-hostname iotedged[3865]: 2021-04-20T09:30:30Z [INFO] - Using runtime network id azure-iot-edge Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully initialized module runtime Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Finished initializing the module runtime. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping all modules... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_8... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_5... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_2... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_3... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_7... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module edgeHub... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_4... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_1... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module custom_module_6... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Stopping module edgeAgent... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_5 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_2 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_3 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_7 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module edgeHub Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_4 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_8 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_1 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module edgeAgent Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - Could not stop module custom_module_6 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [WARN] - caused by: Target of operation already in this state Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Finished stopping modules. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_8... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_5... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_2... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_3... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_7... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module edgeHub... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_4... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_1... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module custom_module_6... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Removing module edgeAgent... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_7 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_5 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_6 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module edgeAgent Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module edgeHub Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_3 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_4 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_1 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_8 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Successfully removed module custom_module_2 Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Detecting if configuration file has changed... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - No change to configuration file detected. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Edge issuer CA expiration date: 2036-04-15T16:01:24Z Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Obtaining workload CA succeeded. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Starting management API... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Starting workload API... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Starting watchdog with 60 second frequency... Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Checking edge runtime status Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - [mgmt] - - - [2021-04-20 09:30:31.987637083 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:31 device-hostname iotedged[3865]: 2021-04-20T09:30:31Z [INFO] - Creating and starting edge runtime module edgeAgent Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.272757360 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.273108869 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.283406597 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.318455546 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.323920268 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.329553427 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.361260252 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.373695784 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.395629516 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.405369953 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.429783624 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.446491279 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.451022201 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.485391101 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.496192472 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - [mgmt] - - - [2021-04-20 09:30:32.521920566 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:32 device-hostname iotedged[3865]: 2021-04-20T09:30:32Z [INFO] - Updating identity for module $edgeAgent Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.380888054 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.380887950 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.385376269 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.423023960 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.438553597 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.441051401 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0... Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.470321776 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.487225419 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.501872455 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.522384003 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.556238842 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.568130575 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.582161154 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.614128291 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.628039183 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.676130070 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.676130018 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.725754232 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:33 device-hostname iotedged[3865]: 2021-04-20T09:30:33Z [INFO] - [mgmt] - - - [2021-04-20 09:30:33.747320100 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:30:34 device-hostname iotedged[3865]: 2021-04-20T09:30:34Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0 Apr 20 11:30:34 device-hostname iotedged[3865]: 2021-04-20T09:30:34Z [INFO] - Creating module edgeAgent... Apr 20 11:30:34 device-hostname iotedged[3865]: 2021-04-20T09:30:34Z [INFO] - Successfully created module edgeAgent Apr 20 11:30:34 device-hostname iotedged[3865]: 2021-04-20T09:30:34Z [INFO] - Starting module edgeAgent... Apr 20 11:30:36 device-hostname iotedged[3865]: 2021-04-20T09:30:36Z [INFO] - Successfully started module edgeAgent Apr 20 11:30:41 device-hostname iotedged[3865]: 2021-04-20T09:30:41Z [INFO] - [work] - - - [2021-04-20 09:30:41.728342930 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:30:43 device-hostname iotedged[3865]: 2021-04-20T09:30:43Z [INFO] - Querying system info... Apr 20 11:30:44 device-hostname iotedged[3865]: none Apr 20 11:30:44 device-hostname iotedged[3865]: 2021-04-20T09:30:44Z [INFO] - Successfully queried system info Apr 20 11:30:44 device-hostname iotedged[3865]: 2021-04-20T09:30:44Z [INFO] - [mgmt] - - - [2021-04-20 09:30:44.074979834 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Apr 20 11:30:48 device-hostname iotedged[3865]: 2021-04-20T09:30:48Z [INFO] - Querying system info... Apr 20 11:30:48 device-hostname iotedged[3865]: none Apr 20 11:30:48 device-hostname iotedged[3865]: 2021-04-20T09:30:48Z [INFO] - Successfully queried system info Apr 20 11:30:48 device-hostname iotedged[3865]: 2021-04-20T09:30:48Z [INFO] - [mgmt] - - - [2021-04-20 09:30:48.199043031 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Apr 20 11:30:48 device-hostname iotedged[3865]: 2021-04-20T09:30:48Z [INFO] - [mgmt] - - - [2021-04-20 09:30:48.688401399 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-) Apr 20 11:30:49 device-hostname iotedged[3865]: 2021-04-20T09:30:49Z [INFO] - [work] - - - [2021-04-20 09:30:49.164944652 UTC] "POST /modules/%24edgeAgent/genid/redacted/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Apr 20 11:30:51 device-hostname iotedged[3865]: 2021-04-20T09:30:51Z [INFO] - [work] - - - [2021-04-20 09:30:51.500532320 UTC] "POST /modules/%24edgeAgent/genid/redacted/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 10057 "-" "-" auth_id(-) Apr 20 11:30:52 device-hostname iotedged[3865]: 2021-04-20T09:30:52Z [INFO] - [mgmt] - - - [2021-04-20 09:30:52.089079430 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1031 "-" "-" auth_id(-) Apr 20 11:30:54 device-hostname iotedged[3865]: 2021-04-20T09:30:54Z [INFO] - [mgmt] - - - [2021-04-20 09:30:54.108922076 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-) Apr 20 11:30:54 device-hostname iotedged[3865]: 2021-04-20T09:30:54Z [INFO] - [mgmt] - - - [2021-04-20 09:30:54.319063221 UTC] "PUT /identities/custom_module_3?api-version=2020-07-07 HTTP/1.1" 200 OK 97 "-" "-" auth_id(-) Apr 20 11:30:55 device-hostname iotedged[3865]: 2021-04-20T09:30:55Z [INFO] - [mgmt] - - - [2021-04-20 09:30:55.017417424 UTC] "PUT /identities/custom_module_8?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Apr 20 11:30:57 device-hostname iotedged[3865]: 2021-04-20T09:30:57Z [INFO] - [mgmt] - - - [2021-04-20 09:30:57.464810408 UTC] "PUT /identities/custom_module_2?api-version=2020-07-07 HTTP/1.1" 200 OK 102 "-" "-" auth_id(-) Apr 20 11:30:57 device-hostname iotedged[3865]: 2021-04-20T09:30:57Z [INFO] - [mgmt] - - - [2021-04-20 09:30:57.468305345 UTC] "PUT /identities/custom_module_6?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Apr 20 11:30:57 device-hostname iotedged[3865]: 2021-04-20T09:30:57Z [INFO] - [mgmt] - - - [2021-04-20 09:30:57.534388829 UTC] "PUT /identities/custom_module_5?api-version=2020-07-07 HTTP/1.1" 200 OK 115 "-" "-" auth_id(-) Apr 20 11:30:58 device-hostname iotedged[3865]: 2021-04-20T09:30:58Z [INFO] - [mgmt] - - - [2021-04-20 09:30:58.458400377 UTC] "PUT /identities/custom_module_4?api-version=2020-07-07 HTTP/1.1" 200 OK 105 "-" "-" auth_id(-) Apr 20 11:30:59 device-hostname iotedged[3865]: 2021-04-20T09:30:59Z [INFO] - [mgmt] - - - [2021-04-20 09:30:59.210269981 UTC] "PUT /identities/custom_module_1?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Apr 20 11:31:00 device-hostname iotedged[3865]: 2021-04-20T09:31:00Z [INFO] - [mgmt] - - - [2021-04-20 09:31:00.078519313 UTC] "PUT /identities/custom_module_7?api-version=2020-07-07 HTTP/1.1" 200 OK 96 "-" "-" auth_id(-) Apr 20 11:31:01 device-hostname iotedged[3865]: 2021-04-20T09:31:01Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10... Apr 20 11:31:01 device-hostname iotedged[3865]: 2021-04-20T09:31:01Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10 Apr 20 11:31:01 device-hostname iotedged[3865]: 2021-04-20T09:31:01Z [INFO] - [mgmt] - - - [2021-04-20 09:31:01.782790061 UTC] "POST /modules/edgeAgent/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:01 device-hostname iotedged[3865]: 2021-04-20T09:31:01Z [INFO] - Updating and starting module edgeAgent Apr 20 11:31:01 device-hostname iotedged[3865]: 2021-04-20T09:31:01Z [INFO] - Removing module edgeAgent... Apr 20 11:31:03 device-hostname iotedged[3865]: 2021-04-20T09:31:03Z [INFO] - Successfully removed module edgeAgent Apr 20 11:31:03 device-hostname iotedged[3865]: 2021-04-20T09:31:03Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10... Apr 20 11:31:04 device-hostname iotedged[3865]: 2021-04-20T09:31:04Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10 Apr 20 11:31:04 device-hostname iotedged[3865]: 2021-04-20T09:31:04Z [INFO] - Creating module edgeAgent... Apr 20 11:31:04 device-hostname iotedged[3865]: 2021-04-20T09:31:04Z [INFO] - Successfully created module edgeAgent Apr 20 11:31:04 device-hostname iotedged[3865]: 2021-04-20T09:31:04Z [INFO] - Starting module edgeAgent Apr 20 11:31:04 device-hostname iotedged[3865]: 2021-04-20T09:31:04Z [INFO] - Starting module edgeAgent... Apr 20 11:31:05 device-hostname iotedged[3865]: 2021-04-20T09:31:05Z [INFO] - Successfully started module edgeAgent Apr 20 11:31:05 device-hostname iotedged[3865]: 2021-04-20T09:31:05Z [INFO] - [mgmt] - - - [2021-04-20 09:31:05.894897773 UTC] "PUT /modules/edgeAgent?api-version=2020-07-07&start=true HTTP/1.1" 200 OK 1574 "-" "-" auth_id(-) Apr 20 11:31:05 device-hostname iotedged[3865]: 2021-04-20T09:31:05Z [ERR!] - server connection error: (unknown) Apr 20 11:31:05 device-hostname iotedged[3865]: 2021-04-20T09:31:05Z [ERR!] - error writing a body to connection: Broken pipe (os error 32) Apr 20 11:31:09 device-hostname iotedged[3865]: 2021-04-20T09:31:09Z [INFO] - [work] - - - [2021-04-20 09:31:09.286697446 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:11 device-hostname iotedged[3865]: 2021-04-20T09:31:11Z [INFO] - Querying system info... Apr 20 11:31:11 device-hostname iotedged[3865]: none Apr 20 11:31:11 device-hostname iotedged[3865]: 2021-04-20T09:31:11Z [INFO] - Successfully queried system info Apr 20 11:31:11 device-hostname iotedged[3865]: 2021-04-20T09:31:11Z [INFO] - [mgmt] - - - [2021-04-20 09:31:11.400298695 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Apr 20 11:31:15 device-hostname iotedged[3865]: 2021-04-20T09:31:15Z [INFO] - [work] - - - [2021-04-20 09:31:15.029789371 UTC] "POST /modules/%24edgeAgent/genid/redacted/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Apr 20 11:31:15 device-hostname iotedged[3865]: 2021-04-20T09:31:15Z [INFO] - Querying system info... Apr 20 11:31:15 device-hostname iotedged[3865]: none Apr 20 11:31:15 device-hostname iotedged[3865]: 2021-04-20T09:31:15Z [INFO] - Successfully queried system info Apr 20 11:31:15 device-hostname iotedged[3865]: 2021-04-20T09:31:15Z [INFO] - [mgmt] - - - [2021-04-20 09:31:15.328824916 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 304 "-" "-" auth_id(-) Apr 20 11:31:15 device-hostname iotedged[3865]: 2021-04-20T09:31:15Z [INFO] - [mgmt] - - - [2021-04-20 09:31:15.812942988 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 725 "-" "-" auth_id(-) Apr 20 11:31:17 device-hostname iotedged[3865]: 2021-04-20T09:31:17Z [INFO] - [work] - - - [2021-04-20 09:31:17.615747062 UTC] "POST /modules/%24edgeAgent/genid/redacted/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 10057 "-" "-" auth_id(-) Apr 20 11:31:18 device-hostname iotedged[3865]: 2021-04-20T09:31:18Z [INFO] - [mgmt] - - - [2021-04-20 09:31:18.207646922 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 1031 "-" "-" auth_id(-) Apr 20 11:31:19 device-hostname iotedged[3865]: 2021-04-20T09:31:19Z [INFO] - [mgmt] - - - [2021-04-20 09:31:19.558272509 UTC] "PUT /identities/custom_module_8?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Apr 20 11:31:22 device-hostname iotedged[3865]: 2021-04-20T09:31:22Z [INFO] - [mgmt] - - - [2021-04-20 09:31:22.728558365 UTC] "PUT /identities/custom_module_5?api-version=2020-07-07 HTTP/1.1" 200 OK 115 "-" "-" auth_id(-) Apr 20 11:31:22 device-hostname iotedged[3865]: 2021-04-20T09:31:22Z [INFO] - [mgmt] - - - [2021-04-20 09:31:22.731556949 UTC] "PUT /identities/custom_module_6?api-version=2020-07-07 HTTP/1.1" 200 OK 100 "-" "-" auth_id(-) Apr 20 11:31:22 device-hostname iotedged[3865]: 2021-04-20T09:31:22Z [INFO] - [mgmt] - - - [2021-04-20 09:31:22.732916476 UTC] "PUT /identities/custom_module_4?api-version=2020-07-07 HTTP/1.1" 200 OK 105 "-" "-" auth_id(-) Apr 20 11:31:24 device-hostname iotedged[3865]: 2021-04-20T09:31:24Z [INFO] - [mgmt] - - - [2021-04-20 09:31:24.531129419 UTC] "PUT /identities/custom_module_1?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-) Apr 20 11:31:25 device-hostname iotedged[3865]: 2021-04-20T09:31:25Z [INFO] - [mgmt] - - - [2021-04-20 09:31:25.306091187 UTC] "PUT /identities/custom_module_7?api-version=2020-07-07 HTTP/1.1" 200 OK 96 "-" "-" auth_id(-) Apr 20 11:31:26 device-hostname iotedged[3865]: 2021-04-20T09:31:26Z [INFO] - [mgmt] - - - [2021-04-20 09:31:26.088357567 UTC] "PUT /identities/custom_module_3?api-version=2020-07-07 HTTP/1.1" 200 OK 97 "-" "-" auth_id(-) Apr 20 11:31:26 device-hostname iotedged[3865]: 2021-04-20T09:31:26Z [INFO] - [mgmt] - - - [2021-04-20 09:31:26.088357724 UTC] "PUT /identities/custom_module_2?api-version=2020-07-07 HTTP/1.1" 200 OK 102 "-" "-" auth_id(-) Apr 20 11:31:26 device-hostname iotedged[3865]: 2021-04-20T09:31:26Z [INFO] - [mgmt] - - - [2021-04-20 09:31:26.150926115 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-) Apr 20 11:31:27 device-hostname iotedged[3865]: 2021-04-20T09:31:27Z [INFO] - Pulling image registry-address/custom_module_8:2.0.0-arm32v7... Apr 20 11:31:29 device-hostname iotedged[3865]: 2021-04-20T09:31:29Z [INFO] - Successfully pulled image registry-address/custom_module_8:2.0.0-arm32v7 Apr 20 11:31:29 device-hostname iotedged[3865]: 2021-04-20T09:31:29Z [INFO] - Creating module custom_module_8... Apr 20 11:31:29 device-hostname iotedged[3865]: 2021-04-20T09:31:29Z [INFO] - Successfully created module custom_module_8 Apr 20 11:31:29 device-hostname iotedged[3865]: 2021-04-20T09:31:29Z [INFO] - [mgmt] - - - [2021-04-20 09:31:29.715825124 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 2263 "-" "-" auth_id(-) Apr 20 11:31:29 device-hostname iotedged[3865]: 2021-04-20T09:31:29Z [INFO] - Starting module custom_module_8... Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - Successfully started module custom_module_8 Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.405812583 UTC] "POST /modules/custom_module_8/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.418951343 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.492326210 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.556046160 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge/custom_module_7:1.0... Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.606857819 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.651784237 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.695613053 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.742007643 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.792913156 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.838332228 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.908787521 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:30 device-hostname iotedged[3865]: 2021-04-20T09:31:30Z [INFO] - [mgmt] - - - [2021-04-20 09:31:30.980200624 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - [mgmt] - - - [2021-04-20 09:31:31.051459456 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 1839 "-" "iotedge/0.1.0" auth_id(-) Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge/custom_module_7:1.0 Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - Creating module custom_module_7... Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - Successfully created module custom_module_7 Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - [mgmt] - - - [2021-04-20 09:31:31.658980099 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1173 "-" "-" auth_id(-) Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - Starting module custom_module_7... Apr 20 11:31:31 device-hostname iotedged[3865]: 2021-04-20T09:31:31Z [INFO] - Checking edge runtime status Apr 20 11:31:32 device-hostname iotedged[3865]: 2021-04-20T09:31:32Z [INFO] - Edge runtime is running. Apr 20 11:31:33 device-hostname iotedged[3865]: 2021-04-20T09:31:33Z [INFO] - Successfully started module custom_module_7 Apr 20 11:31:33 device-hostname iotedged[3865]: 2021-04-20T09:31:33Z [INFO] - [mgmt] - - - [2021-04-20 09:31:33.646967845 UTC] "POST /modules/custom_module_7/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:33 device-hostname iotedged[3865]: 2021-04-20T09:31:33Z [INFO] - Pulling image registry-address/custom_module_5:1.0.0-arm32v7... Apr 20 11:31:34 device-hostname iotedged[3865]: 2021-04-20T09:31:34Z [INFO] - Successfully pulled image registry-address/custom_module_5:1.0.0-arm32v7 Apr 20 11:31:34 device-hostname iotedged[3865]: 2021-04-20T09:31:34Z [INFO] - Creating module custom_module_5... Apr 20 11:31:35 device-hostname iotedged[3865]: 2021-04-20T09:31:35Z [INFO] - [work] - - - [2021-04-20 09:31:35.012489425 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:35 device-hostname iotedged[3865]: 2021-04-20T09:31:35Z [INFO] - Successfully created module custom_module_5 Apr 20 11:31:35 device-hostname iotedged[3865]: 2021-04-20T09:31:35Z [INFO] - [mgmt] - - - [2021-04-20 09:31:35.104086316 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1320 "-" "-" auth_id(-) Apr 20 11:31:35 device-hostname iotedged[3865]: 2021-04-20T09:31:35Z [INFO] - Starting module custom_module_5... Apr 20 11:31:35 device-hostname iotedged[3865]: 2021-04-20T09:31:35Z [INFO] - [work] - - - [2021-04-20 09:31:35.894581836 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:37 device-hostname iotedged[3865]: 2021-04-20T09:31:37Z [INFO] - Successfully started module custom_module_5 Apr 20 11:31:37 device-hostname iotedged[3865]: 2021-04-20T09:31:37Z [INFO] - [mgmt] - - - [2021-04-20 09:31:37.352899731 UTC] "POST /modules/custom_module_5/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:37 device-hostname iotedged[3865]: 2021-04-20T09:31:37Z [INFO] - Pulling image registry-address/custom_module_2:2.0.0-arm32v7... Apr 20 11:31:38 device-hostname iotedged[3865]: 2021-04-20T09:31:38Z [INFO] - Successfully pulled image registry-address/custom_module_2:2.0.0-arm32v7 Apr 20 11:31:38 device-hostname iotedged[3865]: 2021-04-20T09:31:38Z [INFO] - Creating module custom_module_2... Apr 20 11:31:38 device-hostname iotedged[3865]: 2021-04-20T09:31:38Z [INFO] - Successfully created module custom_module_2 Apr 20 11:31:38 device-hostname iotedged[3865]: 2021-04-20T09:31:38Z [INFO] - [mgmt] - - - [2021-04-20 09:31:38.859699500 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1320 "-" "-" auth_id(-) Apr 20 11:31:38 device-hostname iotedged[3865]: 2021-04-20T09:31:38Z [INFO] - Starting module custom_module_2... Apr 20 11:31:40 device-hostname iotedged[3865]: 2021-04-20T09:31:40Z [INFO] - Successfully started module custom_module_2 Apr 20 11:31:40 device-hostname iotedged[3865]: 2021-04-20T09:31:40Z [INFO] - [mgmt] - - - [2021-04-20 09:31:40.960329695 UTC] "POST /modules/custom_module_2/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:41 device-hostname iotedged[3865]: 2021-04-20T09:31:41Z [INFO] - Pulling image registry-address/custom_module_3:2.0.0-arm32v7... Apr 20 11:31:41 device-hostname iotedged[3865]: 2021-04-20T09:31:41Z [INFO] - Successfully pulled image registry-address/custom_module_3:2.0.0-arm32v7 Apr 20 11:31:41 device-hostname iotedged[3865]: 2021-04-20T09:31:41Z [INFO] - Creating module custom_module_3... Apr 20 11:31:42 device-hostname iotedged[3865]: 2021-04-20T09:31:42Z [INFO] - Successfully created module custom_module_3 Apr 20 11:31:42 device-hostname iotedged[3865]: 2021-04-20T09:31:42Z [INFO] - [mgmt] - - - [2021-04-20 09:31:42.239820927 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1442 "-" "-" auth_id(-) Apr 20 11:31:42 device-hostname iotedged[3865]: 2021-04-20T09:31:42Z [INFO] - Starting module custom_module_3... Apr 20 11:31:43 device-hostname iotedged[3865]: 2021-04-20T09:31:43Z [INFO] - [work] - - - [2021-04-20 09:31:43.884851031 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:44 device-hostname iotedged[3865]: 2021-04-20T09:31:44Z [INFO] - Successfully started module custom_module_3 Apr 20 11:31:44 device-hostname iotedged[3865]: 2021-04-20T09:31:44Z [INFO] - [mgmt] - - - [2021-04-20 09:31:44.523189178 UTC] "POST /modules/custom_module_3/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:44 device-hostname iotedged[3865]: 2021-04-20T09:31:44Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-hub:1.0.10... Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-hub:1.0.10 Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - Creating module edgeHub... Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - Successfully created module edgeHub Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - [mgmt] - - - [2021-04-20 09:31:45.677069670 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1device-id "-" "-" auth_id(-) Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - Starting module edgeHub... Apr 20 11:31:45 device-hostname iotedged[3865]: 2021-04-20T09:31:45Z [INFO] - [work] - - - [2021-04-20 09:31:45.747654754 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:48 device-hostname iotedged[3865]: 2021-04-20T09:31:48Z [INFO] - Successfully started module edgeHub Apr 20 11:31:48 device-hostname iotedged[3865]: 2021-04-20T09:31:48Z [INFO] - [mgmt] - - - [2021-04-20 09:31:48.747439336 UTC] "POST /modules/edgeHub/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:49 device-hostname iotedged[3865]: 2021-04-20T09:31:49Z [INFO] - Pulling image registry-address/custom_module_4:2.0.0-arm32v7... Apr 20 11:31:49 device-hostname iotedged[3865]: 2021-04-20T09:31:49Z [INFO] - Successfully pulled image registry-address/custom_module_4:2.0.0-arm32v7 Apr 20 11:31:49 device-hostname iotedged[3865]: 2021-04-20T09:31:49Z [INFO] - Creating module custom_module_4... Apr 20 11:31:49 device-hostname iotedged[3865]: 2021-04-20T09:31:49Z [INFO] - [work] - - - [2021-04-20 09:31:49.969181536 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:50 device-hostname iotedged[3865]: 2021-04-20T09:31:50Z [INFO] - Successfully created module custom_module_4 Apr 20 11:31:50 device-hostname iotedged[3865]: 2021-04-20T09:31:50Z [INFO] - [mgmt] - - - [2021-04-20 09:31:50.222438427 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1410 "-" "-" auth_id(-) Apr 20 11:31:50 device-hostname iotedged[3865]: 2021-04-20T09:31:50Z [INFO] - Starting module custom_module_4... Apr 20 11:31:52 device-hostname iotedged[3865]: 2021-04-20T09:31:52Z [INFO] - Successfully started module custom_module_4 Apr 20 11:31:52 device-hostname iotedged[3865]: 2021-04-20T09:31:52Z [INFO] - [mgmt] - - - [2021-04-20 09:31:52.520995846 UTC] "POST /modules/custom_module_4/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:52 device-hostname iotedged[3865]: 2021-04-20T09:31:52Z [INFO] - Pulling image registry-address/custom_module_6:2.0.0-arm32v7... Apr 20 11:31:53 device-hostname iotedged[3865]: 2021-04-20T09:31:53Z [INFO] - Successfully pulled image registry-address/custom_module_6:2.0.0-arm32v7 Apr 20 11:31:53 device-hostname iotedged[3865]: 2021-04-20T09:31:53Z [INFO] - Creating module custom_module_6... Apr 20 11:31:53 device-hostname iotedged[3865]: 2021-04-20T09:31:53Z [INFO] - Successfully created module custom_module_6 Apr 20 11:31:53 device-hostname iotedged[3865]: 2021-04-20T09:31:53Z [INFO] - [mgmt] - - - [2021-04-20 09:31:53.867814673 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1391 "-" "-" auth_id(-) Apr 20 11:31:53 device-hostname iotedged[3865]: 2021-04-20T09:31:53Z [INFO] - Starting module custom_module_6... Apr 20 11:31:55 device-hostname iotedged[3865]: 2021-04-20T09:31:55Z [INFO] - [work] - - - [2021-04-20 09:31:55.401928728 UTC] "POST /modules/%24edgeHub/genid/redacted/certificate/server?api-version=2019-01-30 HTTP/1.1" 201 Created 9278 "-" "-" auth_id(-) Apr 20 11:31:56 device-hostname iotedged[3865]: 2021-04-20T09:31:56Z [INFO] - Successfully started module custom_module_6 Apr 20 11:31:56 device-hostname iotedged[3865]: 2021-04-20T09:31:56Z [INFO] - [mgmt] - - - [2021-04-20 09:31:56.128311851 UTC] "POST /modules/custom_module_6/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:56 device-hostname iotedged[3865]: 2021-04-20T09:31:56Z [INFO] - Pulling image registry-address/custom_module_1:2.0.0-arm32v7... Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - Successfully pulled image registry-address/custom_module_1:2.0.0-arm32v7 Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - Creating module custom_module_1... Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - [work] - - - [2021-04-20 09:31:57.267736139 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - Successfully created module custom_module_1 Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - [mgmt] - - - [2021-04-20 09:31:57.660536016 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1983 "-" "-" auth_id(-) Apr 20 11:31:57 device-hostname iotedged[3865]: 2021-04-20T09:31:57Z [INFO] - Starting module custom_module_1... Apr 20 11:31:58 device-hostname iotedged[3865]: 2021-04-20T09:31:58Z [INFO] - [work] - - - [2021-04-20 09:31:58.335551388 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Apr 20 11:31:58 device-hostname iotedged[3865]: 2021-04-20T09:31:58Z [INFO] - Successfully started module custom_module_1 Apr 20 11:31:58 device-hostname iotedged[3865]: 2021-04-20T09:31:58Z [INFO] - [mgmt] - - - [2021-04-20 09:31:58.497190606 UTC] "POST /modules/custom_module_1/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-) Apr 20 11:31:58 device-hostname iotedged[3865]: 2021-04-20T09:31:58Z [INFO] - [work] - - - [2021-04-20 09:31:58.759343978 UTC] "POST /modules/%24edgeAgent/genid/redacted/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 10057 "-" "-" auth_id(-) ```

Before 8am, the memory use drops every now and then by a small amount. I am attaching another iotedge log that was recorded during such a drop (at 6:23am):

Log of a small memory drop ``` Apr 20 06:23:47 device-hostname iotedged[1582]: 2021-04-20T04:23:47Z [INFO] - Checking edge runtime status Apr 20 06:23:47 device-hostname iotedged[1582]: 2021-04-20T04:23:47Z [INFO] - Edge runtime is running. Apr 20 06:23:49 device-hostname iotedged[1582]: 2021-04-20T04:23:49Z [INFO] - [mgmt] - - - [2021-04-20 04:23:49.736376729 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 9175 "-" "-" auth_id(-) Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [INFO] - [mgmt] - - - [2021-04-20 04:23:54.872252601 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 9175 "-" "-" auth_id(-) Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [INFO] - Stopping module edgeHub... Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [WARN] - Could not stop module edgeHub Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [WARN] - caused by: Target of operation already in this state Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [INFO] - [mgmt] - - - [2021-04-20 04:23:54.925973268 UTC] "POST /modules/edgeHub/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-) Apr 20 06:23:54 device-hostname iotedged[1582]: 2021-04-20T04:23:54Z [INFO] - Starting module edgeHub... Apr 20 06:23:57 device-hostname iotedged[1582]: 2021-04-20T04:23:57Z [INFO] - Successfully started module edgeHub ```

As a control experiment, I have another device with the exact same configuration/hardware/deployment/OS version, with the only difference being the createOptions.Memory setting unset, and this behavior is completely absent.

I will be increasing the memory available for the edgeHub module to 350MB and see if this fixes the behavior.

AdrienCos commented 3 years ago

Nevermind, it turns out that I had set the memory limit of edgeHub to 105MB instead of 300MB, which would definitely explain the issue. I have increased it to 300MB, and restarted the device.

emilm commented 3 years ago

Memory seems to be stable now with iotedge 1.1.2 (5419edd44f82c229e3bb083cb52b76ce76b383b6) 4 own containers. edge / hub container versions: azureiotedge-hub:1.1.1-linux-arm32v7 (no 1.1.2 available at the time) Hub: "Memory": 209715200 Agent: "Memory": 104857600

image

JardarM commented 3 years ago

Good to see that 1.1.2 seems to be stable, but would appreciate feedback on the cause of this. If we do not know the cause and the fix it is hard to know if the issue will reappear later.

and-rewsmith commented 3 years ago

@JardarM Here is a summary of my testing: https://github.com/Azure/iotedge/issues/4545#issuecomment-818856295

As I mentioned above it is looking like the second case outlined here. The device became unresponsive in my test where I didn't limit memory usage because the remaining system resources (90MB in my test) were taken up, presumably by dotnet but it is hard to say with no metrics, and the device stopped responding to ssh. I believe that the root cause of this issue could be dotnet's memory usage pattern on a pi when in a constrained environment.

The resolution is to use the docker create options to limit the container memory usage. When you do this I recommend leaving ~120 MB available so that you can ssh in and run commands. When Emil said memory usage was stable, he was using the docker create options to limit the memory.

AdrienCos commented 3 years ago

@and-rewsmith After a new week of tests, here are some promising results, with the attached graph:

image

By looking at these graphs, it would indeed seem that upgrading to iotedge 1.1.1 solves the memory leak issue (we only notice an increase of 10MB over 7 days). Further, it would seem that dotnet 3.1 somehow reduces the issue, as its memory consumption slope is is less steep than its 2.1 counterpart.

My next step is to run multiple devices on iotedge 1.1.1, with dotnet 2.1 and 3.1, to assess the impact of the runtime version.

Also, considering that it will be complex for us to keep the OS and iotedge modules in sync, do you know if it is possible to run 1.1.1 modules with a 1.0.10 daemon, or 1.0.10 modules with 1.1.1 daemon?

emilm commented 3 years ago

Same experience here, @AdrienCos . Stable with 1.1.x. Yes there is a challenge keeping containers in sync with the iotedged. Especially if the iotedged is a part of the OS image.

@and-rewsmith I think there's an issue with 1.0.10 vs 1.1 somewhere (containers?) but I can't find out what the differences are.

and-rewsmith commented 3 years ago

By looking at these graphs, it would indeed seem that upgrading to iotedge 1.1.1 solves the memory leak issue (we only notice an increase of 10MB over 7 days)

@AdrienCos Interesting results! I agree in that 1.1.1 seems less likely to cause the problem you mentioned above.

Though, it is important to keep in mind that plotting used-memory can be tricky. Garbage collection can be system dependent. Since gc isn't guaranteed to trigger periodically, it is possible to have a high used-memory slope that eventually gets cleaned up fine by dotnet gc. Likewise it is also possible to have a creeping memory usage over the period of a week that will eventually cause issues. Are all these tests you have done running on the same device at different times, or on different devices at the same time? Is anything else running on the system other than system/custom modules?

Also, considering that it will be complex for us to keep the OS and iotedge modules in sync, do you know if it is possible to run 1.1.1 modules with a 1.0.10 daemon, or 1.0.10 modules with 1.1.1 daemon?

We recommend not mixing the versions of the daemon and system modules. We don't test for compatibility so undefined behavior is possible.

Another thing I was going to mention was regarding my earlier test where I was able to reproduce the ssh hang in an unconstrained memory environment. I found later that the pi in our lab was having some hardware issues. In order to be safe I am going to re-perform this test once I can stabilize our arm setup.

AdrienCos commented 3 years ago

Are all these tests you have done running on the same device at different times, or on different devices at the same time?

All the tests in this graph are done on different devices. However, they all have the exact same hardware (a Raspberry Pi CM3+ on a custom daughterboard), connected to the same Internet network, and running the same Debian-based OS, freshly resintalled before every test.

Is anything else running on the system other than system/custom modules?

Apart from IoT Edge, we also have a Telegraf agent reporting health metrics to Azure Monitor every minute. We also have a logrotate service that rotates all of the logfiles daily at midnight (which is probably the cause of the small dip that can be observed daily).

We recommend not mixing the versions of the daemon and system modules. We don't test for compatibility so undefined behavior is possible.

Noted, I will run a few tests to see if we can get some stability at least for a few days, to allow for potential delays in our update procedure.

I found later that the pi in our lab was having some hardware issues.

If that's OK with you, could you share what kind of hardware issue you were having? It's a long shot, but it's maybe something I can check for on our devices too.

and-rewsmith commented 3 years ago

@AdrienCos The hardware issues was a bad hdmi cord that caused the pi to periodically reboot. I feel it is unlikely to affect my earlier test but wanted to be safe.

Anyways, I did a sanity check yesterday evening where I ran a similar configuration as my earlier ssh hang test (i.e. iotedge with only 90MB of free memory). Except this time I did not run iotedge, just stress --vm 1 --vm-bytes 678M --vm-hang 0. I wanted to see if the ssh hang would reproduce.

When I started this test I ssh'd back in and out to make sure the device was still connected. Around 18hr later the device was unresponsive to ssh. After a few minutes stress command was killed due to OOM. This implies to me that this memory over-consumption causing ssh to hang in memory constrained environments is not related to iotedge or dotnet. What are your thoughts on this?

If this is really the case then I would expect having a manageable workload on the pi (with container memory limits in place), to be the best mitigation.

AdrienCos commented 3 years ago

@and-rewsmith I agree with your analysis, the SSH connection hanging (as well as the Telegraf agent not reporting any data) seems to only be due to a very low amount of available memory, and not directly connected with iotedge.

Regarding container memory limits, from the tests I have done in the past few weeks, it only causes the containers to OOM periodically and restart, and does not trigger the GC. While it prevents the SSH connection from hanging, it still means that our custom modules are susceptible to crash at anytime.

We are also planning on reworking some of our modules to greatly reduce their memory footprint, which should hopefully help on this front.

Hopefully it turns out that iotedge 1.1.1 mostly solves this memory issue, I should have some useful data about this within a few days.

On another note, would you happen to know if the TimeToLiveSecs option for the route definitions causes the messages younger than this duration to be kept in memory, even after being delivered? We currently have this set to 20 days on one of our modules as its data is crucial, and I wonder if this message accumulation could be causing some of the memory strain we are seeing.

and-rewsmith commented 3 years ago

@AdrienCos This TimeToLiveSecs should only affect the disk usage.

AdrienCos commented 3 years ago

Just for posterity, I'm posting the results of my last tests here.

image

This is the graph of used RAM as reported by Telegraf over the course of 6 days. The four devices here have the exact same hardware configuration. They run the following versions of .NET and IoT Edge:

Legend: .NET 2.1 .NET 3.1
IoT Edge 1.0.10 purple red
IoT Edge 1.1.1 turquoise blue
Memory Leak (in MB/day): .NET 2.1 .NET 3.1
IoT Edge 1.0.10 30 30
IoT Edge 1.1.1 3.75 3.5

Note: the drop in memory use that happens daily around midnight is due to a bug in one of our custom modules, that has since been fixed. It is not related to IoT Edge itself.

The main points to draw from this are:

Thanks again for your help @and-rewsmith !