search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.45k stars 458 forks source link

IotHubCommunicationException: MQTT channel open failed #6277

Closed bruno-motacardoso closed 2 years ago

bruno-motacardoso commented 2 years ago

Expected Behavior

Our module should be able to continuously send telemetry messages. Connectivity issues to the cloud and to edgeHub are expected to be handled by Microsoft modules.

Current Behavior

Our module should can't send telemetry message, the following exception is throw:

2022-04-11T06:36:15.860326369Z       Error: MQTT channel open failed.
2022-04-11T06:36:15.860330269Z Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: MQTT channel open failed.
2022-04-11T06:36:15.860334269Z    at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.<>c__DisplayClass102_0.<<CreateChannelFactory>b__0>d.MoveNext()
2022-04-11T06:36:15.860338569Z --- End of stack trace from previous location where exception was thrown ---
2022-04-11T06:36:15.860342269Z    at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenInternalAsync(CancellationToken cancellationToken)
2022-04-11T06:36:15.860345869Z    at Microsoft.Azure.Devices.Client.Transport.Mqtt.MqttTransportHandler.OpenAsync(CancellationToken cancellationToken)
2022-04-11T06:36:15.860349669Z    at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
2022-04-11T06:36:15.860353269Z    at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
2022-04-11T06:36:15.860357469Z --- End of stack trace from previous location where exception was thrown ---
2022-04-11T06:36:15.860360969Z    at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
2022-04-11T06:36:15.860364769Z    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass38_0.<<OpenInternalAsync>b__0>d.MoveNext()
2022-04-11T06:36:15.860383069Z --- End of stack trace from previous location where exception was thrown ---
2022-04-11T06:36:15.860386369Z    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
2022-04-11T06:36:15.860389569Z    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass15_0.<<SendEventAsync>b__0>d.MoveNext()
2022-04-11T06:36:15.860393069Z --- End of stack trace from previous location where exception was thrown ---
2022-04-11T06:36:15.860396169Z    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendEventAsync(Message message, CancellationToken cancellationToken)
2022-04-11T06:36:15.860399469Z    at Microsoft.Azure.Devices.Client.InternalClient.SendEventAsync(String outputName, Message message)
2022-04-11T06:36:15.860403269Z    at M2C.Edge.Module.Acquisition.Orbiwise.Program.PipeMessage(MqttApplicationMessage message, Object userContext) in /app/M2C.Edge.Module.Acquisition.Orbiwise/Program.cs:line 271

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. Develop a custom module and configure iot edge device to use this module
  2. As news features are developed on module, trigger a CI/CD pipeline that redeploy the module.
  3. After some days of running (maybe 1-2 months), the error occurs.

Context (Environment)

Output of iotedge check

Click here ```json { "additional_info": { "aziot_edged_version": "1.2.4", "docker_version": "20.10.6+azure", "now": "2022-04-11T06:54:03.123129869Z", "os": { "arch": "x86_64", "bitness": 64, "id": "ubuntu", "version_id": "18.04" }, "system_info": { "disks": [], "total_ram": "7.77 GiB", "total_swap": "0 B", "used_ram": "1.44 GiB", "used_swap": "0 B" } }, "checks": { "aziot-edge-version": { "result": { "result": "warning", "details": [ "Installed IoT Edge daemon has version 1.2.4 but 1.2.9 is the latest stable version available.\nPlease see https://aka.ms/iotedge-update-runtime for update instructions." ] }, "additional_info": { "actual_version": "1.2.4", "expected_version": "1.2.9" } }, "aziot-edged-config-well-formed": { "result": { "result": "ok" }, "additional_info": {} }, "aziot-version": { "result": { "result": "warning", "details": [ "Installed aziot-identity-service package has version 1.2.3 but 1.2.6 is the latest stable version available.\nPlease see https://aka.ms/aziot-update-runtime for update instructions." ] }, "additional_info": { "actual_version": "1.2.3", "expected_version": "1.2.6" } }, "certd-config-well-formed": { "result": { "result": "ok" }, "additional_info": {} }, "certd-running": { "result": { "result": "ok" }, "additional_info": {} }, "certs-match-private-keys": { "result": { "result": "ok" }, "additional_info": {} }, "certs-preloaded": { "result": { "result": "ok" }, "additional_info": {} }, "certs-read": { "result": { "result": "ok" }, "additional_info": {} }, "check-agent-image": { "result": { "result": "ok" }, "additional_info": {} }, "config-up-to-date": { "result": { "result": "ok" }, "additional_info": {} }, "configs-up-to-date": { "result": { "result": "ok" }, "additional_info": {} }, "connect-management-uri": { "result": { "result": "ok" }, "additional_info": { "connect_management_uri": "unix:///var/run/iotedge/mgmt.sock", "listen_management_uri": "fd://aziot-edged.mgmt.socket" } }, "container-connect-upstream-amqp": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 5671, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-connect-upstream-https": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 443, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-connect-upstream-mqtt": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 8883, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-default-connect-upstream-amqp": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 5671, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-default-connect-upstream-https": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 443, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-default-connect-upstream-mqtt": { "result": { "result": "ok" }, "additional_info": { "diagnostics_image_name": "/azureiotedge-diagnostics:1.2.4", "network_name": "azure-iot-edge", "port_number": 8883, "proxy": null, "upstream_hostname": "***.azure-devices.net" } }, "container-engine-dns": { "result": { "result": "ok" }, "additional_info": { "container_engine_config_path": "/etc/docker/daemon.json", "dns": [ "1.1.1.1" ] } }, "container-engine-ipv6": { "result": { "result": "ignored" }, "additional_info": { "actual_use_ipv6": null, "expected_use_ipv6": false } }, "container-engine-is-moby": { "result": { "result": "ok" }, "additional_info": { "docker_server_version": "20.10.6+azure", "moby_runtime_uri": null } }, "container-engine-logrotate": { "result": { "result": "ok" }, "additional_info": { "daemon_config": { "log-driver": "json-file", "log-opts": { "max-file": "3", "max-size": "10m" } } } }, "container-engine-uri": { "result": { "result": "ok" }, "additional_info": { "docker_host_arg": "unix:///var/run/docker.sock", "docker_server_version": "20.10.6+azure" } }, "container-local-time": { "result": { "result": "ok" }, "additional_info": { "actual_duration": { "nanos": 0, "secs": 1649660045 }, "diff": 0, "expected_duration": { "nanos": 853222928, "secs": 1649660045 } } }, "container-resolve-parent-hostname": { "result": { "result": "ignored" }, "additional_info": {} }, "edge-agent-storage-mounted-from-host": { "result": { "result": "warning", "details": [ "The edgeAgent module is not configured to persist its /tmp/edgeAgent directory on the host filesystem.\nData might be lost if the module is deleted or updated.\nPlease see https://aka.ms/iotedge-storage-host for best practices." ] }, "additional_info": { "container_directories": [ "/var/run/iotedge/mgmt.sock", "/var/run/iotedge/workload.sock" ], "storage_directory": "/tmp/edgeAgent" } }, "edge-hub-storage-mounted-from-host": { "result": { "result": "warning", "details": [ "The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem.\nData might be lost if the module is deleted or updated.\nPlease see https://aka.ms/iotedge-storage-host for best practices." ] }, "additional_info": { "container_directories": [ "/var/run/iotedge/workload.sock" ], "storage_directory": "/tmp/edgeHub" } }, "est-identity-and-bootstrap-certificate-expiry": { "result": { "result": "ignored" }, "additional_info": { "bootstrap_certificate_info": null, "identity_certificate_info": null } }, "host-connect-dps-endpoint": { "result": { "result": "ignored" }, "additional_info": { "dps_endpoint": null, "dps_hostname": null, "proxy": null } }, "host-connect-iothub-amqp": { "result": { "result": "ok" }, "additional_info": { "iothub_hostname": "***.azure-devices.net", "port_number": 5671, "proxy": null } }, "host-connect-iothub-https": { "result": { "result": "ok" }, "additional_info": { "iothub_hostname": "***.azure-devices.net", "port_number": 443, "proxy": null } }, "host-connect-iothub-mqtt": { "result": { "result": "ok" }, "additional_info": { "iothub_hostname": "***.azure-devices.net", "port_number": 8883, "proxy": null } }, "host-local-time": { "result": { "result": "ok" }, "additional_info": { "offset": 0 } }, "hostname": { "result": { "result": "ok" }, "additional_info": { "config_hostname": "***-qlt-edge-vm01", "machine_hostname": "***-qlt-edge-vm01" } }, "identity-certificate-expiry": { "result": { "result": "ignored" }, "additional_info": { "certificate_info": null, "provisioning_mode": "manual-other" } }, "identityd-config-well-formed": { "result": { "result": "ok" }, "additional_info": {} }, "identityd-running": { "result": { "result": "ok" }, "additional_info": {} }, "key-pairs-read": { "result": { "result": "ok" }, "additional_info": {} }, "keyd-config-well-formed": { "result": { "result": "ok" }, "additional_info": {} }, "keyd-running": { "result": { "result": "ok" }, "additional_info": {} }, "local-ca-certificate-expiry": { "result": { "result": "ignored" }, "additional_info": { "certificate_info": null } }, "parent_hostname": { "result": { "result": "ignored" }, "additional_info": { "config_parent_hostname": null } }, "tpmd-config-well-formed": { "result": { "result": "ok" }, "additional_info": {} }, "tpmd-running": { "result": { "result": "ignored" }, "additional_info": {} } } } ```

Device Information

Runtime Versions

Logs

aziot-edged logs ``` Apr 11 06:35:30 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:30Z [INFO] - [mgmt] - - - [2022-04-11 06:35:30.409995142 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:34 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:34Z [INFO] - Checking edge runtime status Apr 11 06:35:34 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:34Z [INFO] - Edge runtime is running. Apr 11 06:35:35 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:35Z [INFO] - [mgmt] - - - [2022-04-11 06:35:35.419680638 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:40 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:40Z [INFO] - [mgmt] - - - [2022-04-11 06:35:40.434849281 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:45Z [INFO] - [mgmt] - - - [2022-04-11 06:35:45.442807263 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - <-- GET /certificates/aziot-edged-ca?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - <-- GET /certificates/aziot-edged-trust-bundle?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - <-- GET /certificates/trust-bundle-user?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - <-- GET /keypair/aziot-edged-ca?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - <-- GET /keypair/device-id?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [ERR!] - error:0909006C:PEM routines:get_name:no start line:../crypto/pem/pem_lib.c:745:Expecting: ANY PRIVATE KEY Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [ERR!] - !!! internal error Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [ERR!] - !!! caused by: could not load key pair Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [ERR!] - !!! caused by: could not load key pair: AZIOT_KEYS_RC_ERR_EXTERNAL Apr 11 06:35:45 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:35:45Z [INFO] - --> 500 {"content-type": "application/json"} Apr 11 06:35:47 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:47Z [INFO] - [mgmt] - - - [2022-04-11 06:35:47.127553295 UTC] "GET /modules/?api-version=2018-06-28 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:50 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:50Z [INFO] - [mgmt] - - - [2022-04-11 06:35:50.461464518 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:35:55 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:35:55Z [INFO] - [mgmt] - - - [2022-04-11 06:35:55.474271640 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:00 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:00Z [INFO] - [mgmt] - - - [2022-04-11 06:36:00.486882121 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:05 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:05Z [INFO] - [mgmt] - - - [2022-04-11 06:36:05.499144228 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:10 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:10Z [INFO] - [mgmt] - - - [2022-04-11 06:36:10.507651968 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:15 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:15Z [INFO] - [mgmt] - - - [2022-04-11 06:36:15.518245960 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:20 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:20Z [INFO] - [mgmt] - - - [2022-04-11 06:36:20.529913596 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:25 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:25Z [INFO] - [mgmt] - - - [2022-04-11 06:36:25.541981271 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:28 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:28Z [INFO] - Querying system resources... Apr 11 06:36:30 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:30Z [INFO] - [mgmt] - - - [2022-04-11 06:36:30.551568363 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:34 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:34Z [INFO] - Checking edge runtime status Apr 11 06:36:34 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:34Z [INFO] - Edge runtime is running. Apr 11 06:36:35 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:35Z [INFO] - [mgmt] - - - [2022-04-11 06:36:35.562423799 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:39 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:39Z [INFO] - [mgmt] - - - [2022-04-11 06:36:39.226226551 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 18571 "-" "-" auth_id(-) Apr 11 06:36:40 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:40Z [INFO] - [mgmt] - - - [2022-04-11 06:36:40.573144869 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:45 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:45Z [INFO] - [mgmt] - - - [2022-04-11 06:36:45.583943273 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:50 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:50Z [INFO] - [mgmt] - - - [2022-04-11 06:36:50.589492672 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:36:55 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:36:55Z [INFO] - [mgmt] - - - [2022-04-11 06:36:55.598326929 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:00 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:00Z [INFO] - [mgmt] - - - [2022-04-11 06:37:00.610532945 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:05 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:05Z [INFO] - [mgmt] - - - [2022-04-11 06:37:05.619959873 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:10 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:10Z [INFO] - [mgmt] - - - [2022-04-11 06:37:10.629453834 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:15 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:15Z [INFO] - [mgmt] - - - [2022-04-11 06:37:15.641624649 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - <-- GET /certificates/aziot-edged-ca?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - <-- GET /certificates/aziot-edged-trust-bundle?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - <-- GET /certificates/trust-bundle-user?api-version=2020-09-01 {"host": "certd.sock"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-certd[1999]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - <-- GET /keypair/aziot-edged-ca?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - <-- GET /keypair/device-id?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [ERR!] - error:0909006C:PEM routines:get_name:no start line:../crypto/pem/pem_lib.c:745:Expecting: ANY PRIVATE KEY Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [ERR!] - !!! internal error Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [ERR!] - !!! caused by: could not load key pair Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [ERR!] - !!! caused by: could not load key pair: AZIOT_KEYS_RC_ERR_EXTERNAL Apr 11 06:37:16 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:16Z [INFO] - --> 500 {"content-type": "application/json"} Apr 11 06:37:17 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:17Z [INFO] - [mgmt] - - - [2022-04-11 06:37:17.573390736 UTC] "GET /modules/?api-version=2018-06-28 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:20 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:20Z [INFO] - [mgmt] - - - [2022-04-11 06:37:20.653098613 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:25 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:25Z [INFO] - [mgmt] - - - [2022-04-11 06:37:25.663242340 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-identityd[1936]: 2022-04-11T06:37:30Z [INFO] - <-- GET /identities/modules/$edgeAgent?api-version=2020-09-01&type=aziot {"content-type": "application/json", "host": "2f72756e2f617a696f742f6964656e74697479642e736f636b:0", "content-length": "40"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- GET /key/device-id?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /sign?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "386"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- GET /key/aziot_identityd_master_id?api-version=2020-09-01 {"host": "keyd.sock"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /derivedkey?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "340"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /derivedkey/export?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "736"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /derivedkey?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "340"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /derivedkey/export?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "748"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-identityd[1936]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - <-- POST /sign?api-version=2020-09-01 {"content-length": "922", "content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-keyd[1968]: 2022-04-11T06:37:30Z [INFO] - --> 200 {"content-type": "application/json"} Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:30Z [INFO] - [work] - - - [2022-04-11 06:37:30.064437699 UTC] "POST /modules/%24edgeAgent/genid/637660860072607002/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Apr 11 06:37:30 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:30Z [INFO] - [mgmt] - - - [2022-04-11 06:37:30.672543422 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4313 "-" "-" auth_id(-) Apr 11 06:37:34 ***-qlt-edge-vm01 aziot-edged[1881]: 2022-04-11T06:37:34Z [INFO] - Checking edge runtime status ```
edge-agent logs ``` 2022-04-11T00:39:38.953662851Z <6> 2022-04-11 00:39:38.953 +00:00 [INF] - Starting compaction of stores 2022-04-11T00:39:38.953708751Z <6> 2022-04-11 00:39:38.953 +00:00 [INF] - Starting compaction of store moduleState 2022-04-11T00:39:38.953716651Z <6> 2022-04-11 00:39:38.953 +00:00 [INF] - Starting compaction of store deploymentConfig 2022-04-11T00:39:38.953723051Z <6> 2022-04-11 00:39:38.953 +00:00 [INF] - Starting compaction of store default 2022-04-11T00:50:01.010027079Z <6> 2022-04-11 00:50:01.009 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T00:50:01.021861973Z <6> 2022-04-11 00:50:01.021 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T00:50:01.022649780Z <6> 2022-04-11 00:50:01.022 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T01:50:01.026097357Z <6> 2022-04-11 01:50:01.025 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T01:50:01.041282581Z <6> 2022-04-11 01:50:01.041 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T01:50:01.042354890Z <6> 2022-04-11 01:50:01.042 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T02:39:38.955105153Z <6> 2022-04-11 02:39:38.954 +00:00 [INF] - Starting compaction of stores 2022-04-11T02:39:38.955169954Z <6> 2022-04-11 02:39:38.954 +00:00 [INF] - Starting compaction of store moduleState 2022-04-11T02:39:38.955193554Z <6> 2022-04-11 02:39:38.954 +00:00 [INF] - Starting compaction of store deploymentConfig 2022-04-11T02:39:38.955199254Z <6> 2022-04-11 02:39:38.955 +00:00 [INF] - Starting compaction of store default 2022-04-11T02:50:01.041163031Z <6> 2022-04-11 02:50:01.040 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T02:50:01.051756318Z <6> 2022-04-11 02:50:01.051 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T02:50:01.052574825Z <6> 2022-04-11 02:50:01.052 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T03:50:01.052821159Z <6> 2022-04-11 03:50:01.052 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T03:50:01.065438264Z <6> 2022-04-11 03:50:01.065 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T03:50:01.066073870Z <6> 2022-04-11 03:50:01.065 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T04:39:38.952673589Z <6> 2022-04-11 04:39:38.952 +00:00 [INF] - Starting compaction of stores 2022-04-11T04:39:38.952730490Z <6> 2022-04-11 04:39:38.952 +00:00 [INF] - Starting compaction of store moduleState 2022-04-11T04:39:38.953011093Z <6> 2022-04-11 04:39:38.952 +00:00 [INF] - Starting compaction of store deploymentConfig 2022-04-11T04:39:38.953085694Z <6> 2022-04-11 04:39:38.952 +00:00 [INF] - Starting compaction of store default 2022-04-11T04:50:01.065944893Z <6> 2022-04-11 04:50:01.065 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T04:50:01.077782708Z <6> 2022-04-11 04:50:01.077 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T04:50:01.078629917Z <6> 2022-04-11 04:50:01.078 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T05:50:01.078952824Z <6> 2022-04-11 05:50:01.078 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T05:50:01.099969700Z <6> 2022-04-11 05:50:01.099 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T05:50:01.100740807Z <6> 2022-04-11 05:50:01.100 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T06:39:38.953378112Z <6> 2022-04-11 06:39:38.953 +00:00 [INF] - Starting compaction of stores 2022-04-11T06:39:38.953425513Z <6> 2022-04-11 06:39:38.953 +00:00 [INF] - Starting compaction of store moduleState 2022-04-11T06:39:38.953494213Z <6> 2022-04-11 06:39:38.953 +00:00 [INF] - Starting compaction of store deploymentConfig 2022-04-11T06:39:38.953501213Z <6> 2022-04-11 06:39:38.953 +00:00 [INF] - Starting compaction of store default 2022-04-11T06:50:01.098010347Z <6> 2022-04-11 06:50:01.097 +00:00 [INF] - Starting periodic operation refresh twin config... 2022-04-11T06:50:01.109224739Z <6> 2022-04-11 06:50:01.109 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 15 and reported properties version 359. 2022-04-11T06:50:01.109988145Z <6> 2022-04-11 06:50:01.109 +00:00 [INF] - Successfully completed periodic operation refresh twin config 2022-04-11T06:57:43.087073896Z <6> 2022-04-11 06:57:43.086 +00:00 [INF] - Updated reported properties ```
edge-hub logs ``` 2022-04-11T05:45:29.353704589Z <4> 2022-04-11 05:45:29.352 +00:00 [WRN] - Error getting edge hub configuration. 2022-04-11T05:45:29.353709389Z System.ObjectDisposedException: The CancellationTokenSource has been disposed. 2022-04-11T05:45:29.353724890Z at System.Threading.CancellationTokenSource.ThrowObjectDisposedException() 2022-04-11T05:45:29.353728790Z at Microsoft.Azure.Devices.Routing.Core.Router.ReplaceRoutes(ISet`1 newRoutes) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Routing.Core/Router.cs:line 165 2022-04-11T05:45:29.353732690Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.UpdateRoutes(IReadOnlyDictionary`2 routes, Boolean replaceExisting) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 135 2022-04-11T05:45:29.353736590Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.b__11_0(EdgeHubConfig ehc) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 110 2022-04-11T05:45:29.353740690Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.UpdateConfig(Option`1 edgeHubConfig) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 112 2022-04-11T05:45:29.353744490Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.PullConfig(Func`2 configGetter) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 93 2022-04-11T05:45:29.353748290Z <6> 2022-04-11 05:45:29.353 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config 2022-04-11T05:45:29.537085946Z <6> 2022-04-11 05:45:29.532 +00:00 [INF] - Updated reported properties for ***-qlt-edge01/$edgeHub 2022-04-11T05:49:50.539103147Z <6> 2022-04-11 05:49:50.538 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T05:54:50.537360676Z <6> 2022-04-11 05:54:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T05:59:04.014145589Z <6> 2022-04-11 05:59:04.013 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 2022-04-11T05:59:04.014955696Z <6> 2022-04-11 05:59:04.014 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 and 0 messages from message store. 2022-04-11T05:59:34.014587398Z <6> 2022-04-11 05:59:34.014 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 2022-04-11T05:59:34.015087202Z <6> 2022-04-11 05:59:34.014 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 and 0 messages from message store. 2022-04-11T05:59:50.537788831Z <6> 2022-04-11 05:59:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:00:04.016225595Z <6> 2022-04-11 06:00:04.015 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub 2022-04-11T06:00:04.016688599Z <6> 2022-04-11 06:00:04.016 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. 2022-04-11T06:00:34.014533336Z <6> 2022-04-11 06:00:34.014 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/filteringmodule/input1 2022-04-11T06:00:34.014967540Z <6> 2022-04-11 06:00:34.014 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/filteringmodule/input1 and 0 messages from message store. 2022-04-11T06:04:50.536910012Z <6> 2022-04-11 06:04:50.536 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:09:50.539069622Z <6> 2022-04-11 06:09:50.538 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:14:50.536635688Z <6> 2022-04-11 06:14:50.536 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:19:50.536662606Z <6> 2022-04-11 06:19:50.536 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:20:28.768229394Z <6> 2022-04-11 06:20:28.767 +00:00 [INF] - Starting refresh of device scope identities cache 2022-04-11T06:24:50.537577597Z <6> 2022-04-11 06:24:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:29:50.537424618Z <6> 2022-04-11 06:29:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:31:04.017729162Z <6> 2022-04-11 06:31:04.017 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 2022-04-11T06:31:04.018389068Z <6> 2022-04-11 06:31:04.018 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 and 0 messages from message store. 2022-04-11T06:31:34.018592342Z <6> 2022-04-11 06:31:34.018 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 2022-04-11T06:31:34.019307148Z <6> 2022-04-11 06:31:34.019 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 and 0 messages from message store. 2022-04-11T06:32:04.018378729Z <6> 2022-04-11 06:32:04.018 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub 2022-04-11T06:32:04.018779433Z <6> 2022-04-11 06:32:04.018 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. 2022-04-11T06:32:34.023884980Z <6> 2022-04-11 06:32:34.023 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/filteringmodule/input1 2022-04-11T06:32:34.024385584Z <6> 2022-04-11 06:32:34.024 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/filteringmodule/input1 and 0 messages from message store. 2022-04-11T06:34:50.534715904Z <6> 2022-04-11 06:34:50.534 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:39:49.138345117Z <6> 2022-04-11 06:39:49.137 +00:00 [INF] - Starting compaction of stores 2022-04-11T06:39:49.138397118Z <6> 2022-04-11 06:39:49.137 +00:00 [INF] - Starting compaction of store DeviceScopeCache 2022-04-11T06:39:49.138501118Z <6> 2022-04-11 06:39:49.137 +00:00 [INF] - Starting compaction of store twins 2022-04-11T06:39:49.138530519Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store ***-qlt-edge01/orbiwisenkedecodingmodule/input1 2022-04-11T06:39:49.138537819Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store checkpoints 2022-04-11T06:39:49.138544019Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 2022-04-11T06:39:49.138550519Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store messages 2022-04-11T06:39:49.138556519Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store iothub 2022-04-11T06:39:49.138565419Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store EdgeTwin 2022-04-11T06:39:49.138571519Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store MetadataStore 2022-04-11T06:39:49.138577619Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store default 2022-04-11T06:39:49.138583619Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store sessions 2022-04-11T06:39:49.138589719Z <6> 2022-04-11 06:39:49.138 +00:00 [INF] - Starting compaction of store ***-qlt-edge01/filteringmodule/input1 2022-04-11T06:39:50.537377757Z <6> 2022-04-11 06:39:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:44:50.538421566Z <6> 2022-04-11 06:44:50.538 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:45:29.353953459Z <6> 2022-04-11 06:45:29.353 +00:00 [INF] - Starting periodic operation Get EdgeHub config... 2022-04-11T06:45:29.499714626Z <6> 2022-04-11 06:45:29.498 +00:00 [INF] - Obtained edge hub config from module twin 2022-04-11T06:45:29.499751627Z <4> 2022-04-11 06:45:29.498 +00:00 [WRN] - Error getting edge hub configuration. 2022-04-11T06:45:29.499756027Z System.ObjectDisposedException: The CancellationTokenSource has been disposed. 2022-04-11T06:45:29.499759827Z at System.Threading.CancellationTokenSource.ThrowObjectDisposedException() 2022-04-11T06:45:29.499763627Z at Microsoft.Azure.Devices.Routing.Core.Router.ReplaceRoutes(ISet`1 newRoutes) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Routing.Core/Router.cs:line 165 2022-04-11T06:45:29.499767527Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.UpdateRoutes(IReadOnlyDictionary`2 routes, Boolean replaceExisting) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 135 2022-04-11T06:45:29.499771627Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.b__11_0(EdgeHubConfig ehc) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 110 2022-04-11T06:45:29.499775727Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.UpdateConfig(Option`1 edgeHubConfig) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 112 2022-04-11T06:45:29.499779727Z at Microsoft.Azure.Devices.Edge.Hub.Core.Config.ConfigUpdater.PullConfig(Func`2 configGetter) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/config/ConfigUpdater.cs:line 93 2022-04-11T06:45:29.499793927Z <6> 2022-04-11 06:45:29.499 +00:00 [INF] - Successfully completed periodic operation Get EdgeHub config 2022-04-11T06:45:29.671079498Z <6> 2022-04-11 06:45:29.670 +00:00 [INF] - Updated reported properties for ***-qlt-edge01/$edgeHub 2022-04-11T06:49:50.537499714Z <6> 2022-04-11 06:49:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:54:50.537376079Z <6> 2022-04-11 06:54:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T06:59:50.538066340Z <6> 2022-04-11 06:59:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T07:03:04.025176488Z <6> 2022-04-11 07:03:04.024 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 2022-04-11T07:03:04.025806394Z <6> 2022-04-11 07:03:04.025 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisenkedecodingmodule/input1 and 0 messages from message store. 2022-04-11T07:03:34.027989738Z <6> 2022-04-11 07:03:34.027 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 2022-04-11T07:03:34.028022938Z <6> 2022-04-11 07:03:34.027 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/orbiwisetetraedredecodingmodule/input1 and 0 messages from message store. 2022-04-11T07:04:04.025858520Z <6> 2022-04-11 07:04:04.025 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint iothub 2022-04-11T07:04:04.026101922Z <6> 2022-04-11 07:04:04.025 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint iothub and 0 messages from message store. 2022-04-11T07:04:34.026744496Z <6> 2022-04-11 07:04:34.026 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint ***-qlt-edge01/filteringmodule/input1 2022-04-11T07:04:34.026935698Z <6> 2022-04-11 07:04:34.026 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint ***-qlt-edge01/filteringmodule/input1 and 0 messages from message store. 2022-04-11T07:04:50.535996109Z <6> 2022-04-11 07:04:50.535 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T07:09:50.538017938Z <6> 2022-04-11 07:09:50.537 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T07:14:50.535042255Z <6> 2022-04-11 07:14:50.534 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T07:19:50.536979733Z <6> 2022-04-11 07:19:50.536 +00:00 [INF] - Entering periodic task to reauthenticate connected clients 2022-04-11T07:20:29.601318942Z <6> 2022-04-11 07:20:29.601 +00:00 [INF] - Starting refresh of device scope identities cache ```

Additional Information

I am using my own certificates on the iot edge config (/etc/aziot/config.toml):

trust_bundle_cert = "file:///certs/aziot-certs/***-iot.intermediate-full-chain.cert.pem"

[edge_ca]
cert = "file:///certs/aziot-certs/iot-edge-device-ca-***-qlt-edge-vm01.cert.pem"                # file URI
pk = "file:///certs/aziot-keys/iot-edge-device-ca-***-qlt-edge-vm01.key.pem"              # file URI, or..
nyanzebra commented 2 years ago

Hi @bruno-motacardoso, just some clarifying questions:

  1. It is listed that 'After some days of running (maybe 1-2 months), the error occurs.' is this something that is sometimes happening after months of running? Or is it something that after running for a month or so, it now fails every couple of days?
  2. Is the iotedge check from the time you see the issue or is at a different time?
  3. From the logs from edgehub it is only showing error fetching configuration, is there also error about accepting connection from your custom module? As from the logs that I assume to be your custom module where this happens: Error: MQTT channel open failed; I am curious if there are any debug logs from your module or edgehub that might indicate why connectivity from your module to edgehub failed? https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2020-11 for documentation on how to set debug logs.
bruno-motacardoso commented 2 years ago

Hi @nyanzebra , see below my clarifications:

  1. It fails every couple of days.
  2. Yes, the iotedge check is from the time when the issue was present.

  3. Yes, it happebs in my module at this line:

    try
{
await moduleClient.SendEventAsync("output1", pipeMessage); <---- exception at this line
}
catch (Exception ex)
{
_logger.LogError(ex, "Error: {Message}", ex.Message);

if (ex.InnerException != null)
{
    _logger.LogWarning(ex.InnerException, "Inner exception : {InnerMessage}.", ex.InnerException.Message);
}

return MessageResponse.Abandoned;
}

The moduleClient is defined like this :

// Open a connection to the Edge runtime
_ioTHubModuleClient = await ModuleClient.CreateFromEnvironmentAsync(settings);

_ioTHubModuleClient.SetRetryPolicy(new RetryPolicy(_logger, 3));

_ioTHubModuleClient.SetConnectionStatusChangesHandler(ConnectionStatusChanged);

await _ioTHubModuleClient.OpenAsync();

_logger.LogInformation("IoT Hub module client initialized: {ProductInfo}", _ioTHubModuleClient.ProductInfo);
nyanzebra commented 2 years ago

Okay, interesting, from the logs/check I don't see anything too out of the ordinary... other than not being able to load the key pair (this was not configured with PKCS#11 so it loaded the keypair from a file, but the file didn't contain a keypair)

Are there any additional errors or logs from edgeHub (by the way, this is the doc for enabling debug logs in edgeHub and other edge modules: https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2020-11)? From what I see there it seems like there is likely connectivity issue, but if iotedge check is current with the time in which the issue was seen then it seems like certificates and connectivity are good...

Also, what SDK and version are you using? Are there additional logs beyond the stack trace on the mqtt channel failing to open?

Final question for now, what are you doing to get the modules running again? A simple restart? I ask in that I am curious if there are any other resources that might be getting used up like memory that could cause the process to slow down or not function properly. The check seems to show good memory usage, but still want to double check and understand your device situation fully.

nyanzebra commented 2 years ago

@bruno-motacardoso if you are willing to share a support bundle that will help in debugging, if you don't want to reveal anything you don't want to in the logs then we can open an internal issue and support you that way too.

For support bundle please see: https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2020-11

jlian commented 2 years ago

@bruno-motacardoso have you had the chance to try @nyanzebra suggestions?

varunpuranik commented 2 years ago

@drwill-ms / @azabbasi - any idea why/when the module client could get into this state and throw the exception above to application code?

drwill-ms commented 2 years ago

Connectivity issues to the cloud and to edgeHub are expected to be handled by Microsoft modules.

The SDK will retry only so much before it gives up on a connection. It is expected of a device/module developer to monitor the connection status callback and take action in some cases. We have a device app sample showing how to responsibly take action. I see this line in the code snippet _ioTHubModuleClient.SetConnectionStatusChangesHandler(ConnectionStatusChanged);, but wonder what the implementation of the handler is.

Getting SDK logs during a repro might help.

jlian commented 2 years ago

@bruno-motacardoso :

bruno-motacardoso commented 2 years ago

@nyanzebra thanks for your help. See below more details about your questions.

Okay, interesting, from the logs/check I don't see anything too out of the ordinary... other than not being able to load the key pair (this was not configured with PKCS#11 so it loaded the keypair from a file, but the file didn't contain a keypair)

It means that my custom TLS certificate is not used by the iotedge ? If my certificate is not used, maybe the default certifcate is used and it causes problems when it is trying to renew it ?

Are there any additional errors or logs from edgeHub (by the way, this is the doc for enabling debug logs in edgeHub and other edge modules: https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2020-11)? From what I see there it seems like there is likely connectivity issue, but if iotedge check is current with the time in which the issue was seen then it seems like certificates and connectivity are good...

Yes iotedge check seems good.. I enabled debug for edgeHub by running the command iotedge system set-log-level debug. Now I have to wait to have the problem another time and have the debug logs.. (I cannot trigger the problem)

Also, what SDK and version are you using? Are there additional logs beyond the stack trace on the mqtt channel failing to open?

I use the framework netcoreapp3.1 and the dependency <PackageReference Include="Microsoft.Azure.Devices.Client" Version="1.37.2" /> on my iotedge modules.

Final question for now, what are you doing to get the modules running again? A simple restart? I ask in that I am curious if there are any other resources that might be getting used up like memory that could cause the process to slow down or not function properly. The check seems to show good memory usage, but still want to double check and understand your device situation fully.

I simply do a iotedge system restart and all works fine.

PS: The problem has occured two more times this week in two other vms (iotedge devices). I created a support bundle, should I send it to microsoft ? Is it possible to anonymise it ?

bruno-motacardoso commented 2 years ago

@jlian :

  • Does the issue persist (e.g. until restart) or does the module eventually recover?

The issues appears each N weeks (btw 1 and 2 months)

  • Do you experience any message loss?

All the communication and modules are down and I restart it to recover the running state. So all the message are lost. This is the reason why this problem is critical in my app.

  • Have you considered @drwill-ms suggestion?

See my message above.

  • Do you have any IoT Hub diagnostic logs?

Yes diagnotics settings are enabled on my iot hub. Where can I find the logs for my iotedge issue ? I think that no log is upload to iohub because the communication btw my modules and edgeHub is lost..

nyanzebra commented 2 years ago

@varunpuranik, do we have a link for creating a support issue internal to MSFT?

nyanzebra commented 2 years ago

@bruno-motacardoso you can log a bug on us and then we can ask for the support-bundle

bishal41 commented 2 years ago

@bruno-motacardoso here is the link to create a support request https://azure.microsoft.com/en-us/support/create-ticket/

In the wizard for "Create a support request" you can select Issue type = "Technical" and then Service = "IoT Edge"

Once you open the support request, please let us know that way we are in sync and look at the support bundle to take this forward.

bishal41 commented 2 years ago

@bruno-motacardoso, were you able to open a support request using the instructions above? Please let us know so we can track the support request and get the logs and perhaps close this in GH?

bishal41 commented 2 years ago

@bruno-motacardoso following up on this again to ensure your issue is resolved and whether further action is needed on this? Please let us know.

bruno-motacardoso commented 2 years ago

@bishal41 I had the problem, one more time this morning. So I created a support request (2206020050000495) with iotedge support-bundle attached.

github-actions[bot] commented 2 years ago

This issue is being marked as stale because it has been open for 30 days with no activity.

micahl commented 2 years ago

@bruno-motacardoso please use the support request to provide the team with debug logs and SDK logs. Closing this issue.