iotedge: IotHubCommunicationException: MQTT channel open failed

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 

{
  "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

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

Runtime Versions

  • aziot-edged [run iotedge version]: 1.2.4
  • Edge Agent [image tag (e.g. 1.0.0)]: 1.1
  • Edge Hub [image tag (e.g. 1.0.0)]: 1.1
  • Docker/Moby [run docker version]: 20.10.6+azure

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

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 18 (10 by maintainers)

Most upvoted comments

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

+1
bruno-motacardoso on Jun 2, 2022
Read more comments on GitHub
← iotedge: IotHub call timed out - direct methods stop working, D2C messages unaffected
iotedge: Issue installing IoTEdge on RPI4 (Errors were encountered while processing: aufs-dkms) →