Edge modules fail to connect on EdgeHub after certificate update

giovannimele commented 1 year ago

Expected Behavior

We have a cron job that is updating production certificates in /etc/aziot/ . The config.toml points on these certificates. We expect that when the edge device is restarted, all modules are started nd can send data to the IOTHub

Current Behavior

The EdgeAgent and EdgeHub modules are started, but all other modules crash with error :

Unhandled exception. System.AggregateException: One or more errors occurred. (TLS authentication error.) ---> System.Security.Authentication.AuthenticationException: TLS authentication error. ---> System.AggregateException: One or more errors occurred. (The remote certificate is invalid according to the validation procedure.) ---> System.Security.Authentication.AuthenticationException: The remote certificate is invalid according to the validation procedure. at System.Net.Security.SslStream.StartSendAuthResetSignal(ProtocolToken message, AsyncProtocolRequest asyncRequest, ExceptionDispatchInfo exception) at System.Net.Security.SslStream.CheckCompletionBeforeNextReceive(ProtocolToken message, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslStream.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslStream.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslStream.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest) at System.Net.Security.SslStream.PartialFrameCallback(AsyncProtocolRequest asyncRequest)

This happen in our code when we initialize the edgeClient:

// Open a connection to the Edge runtime edgeClient?.OpenAsync().Wait();

To solve this problem, the only solution is to stop the iotedge service, clean docker and then restart the iotedge service:

sudo iotedge system stop sudo docker prune -a -f sudo system iotedge system restart

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

Update the iotedge certificate and located in /etc/aziot
Restart the edge device
Wait for the edgeAgent to start

Context (Environment)

Ubuntu 18.04.6 LTS

Output of `iotedge check`

Click here

``` Configuration checks (aziot-identity-service) --------------------------------------------- √ keyd configuration is well-formed - OK √ certd configuration is well-formed - OK √ tpmd configuration is well-formed - OK √ identityd configuration is well-formed - OK √ daemon configurations up-to-date with config.toml - OK √ identityd config toml file specifies a valid hostname - OK √ aziot-identity-service package is up-to-date - OK ‼ host time is close to reference time - Warning Could not query NTP server √ preloaded certificates are valid - OK √ keyd is running - OK √ certd is running - OK √ tpmd is running - OK √ identityd is running - OK √ read all preloaded certificates from the Certificates Service - OK √ read all preloaded key pairs from the Keys Service - OK √ check all EST server URLs utilize HTTPS - OK √ ensure all preloaded certificates match preloaded private keys with the same ID - OK Connectivity checks (aziot-identity-service) -------------------------------------------- ‼ host can connect to and perform TLS handshake with iothub AMQP port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. ‼ host can connect to and perform TLS handshake with iothub MQTT port - Warning Could not retrieve iothub_hostname from provisioning file. Please specify the backing IoT Hub name using --iothub-hostname switch if you have that information. Since no hostname is provided, all hub connectivity tests will be skipped. √ host can connect to and perform TLS handshake with DPS endpoint - OK Configuration checks -------------------- √ aziot-edged configuration is well-formed - OK √ configuration up-to-date with config.toml - OK √ container engine is installed and functional - OK √ configuration has correct URIs for daemon mgmt endpoint - OK ‼ aziot-edge package is up-to-date - Warning Installed IoT Edge daemon has version 1.4.2 but 1.4.3 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ container time is close to host time - OK ‼ DNS server - Warning Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub. Please see https://aka.ms/iotedge-prod-checklist-dns for best practices. You can ignore this warning if you are setting DNS server per module in the Edge deployment. √ production readiness: logs policy - OK √ production readiness: Edge Agent's storage directory is persisted on the host filesystem - OK √ production readiness: Edge Hub's storage directory is persisted on the host filesystem - OK √ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK Connectivity checks ------------------- 26 check(s) succeeded. 6 check(s) raised warnings. Re-run with --verbose for more details. 7 check(s) were skipped due to errors from other checks. Re-run with --verbose for more details. ```

Device Information

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

Runtime Versions

aziot-edged [run iotedge version]: iotedge 1.4.2
Edge Agent [image tag (e.g. 1.0.0)]: 1.2.9 or 1.4.2
Edge Hub [image tag (e.g. 1.0.0)]: 1.2.9 or 1.4.2
Docker/Moby [run docker version]: 20.10.22+azure-1

Note: when using Windows containers on Windows, run docker -H npipe:////./pipe/iotedge_moby_engine version instead

Logs

aziot-edged logs

``` REMARKS: all other modules except the opcuapublisher are not started (probably because they failed so many times?????) Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Starting workload API... Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Workload API stopped Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Edge runtime status is failed, starting module now... Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Starting module edgeAgent... Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Starting new listener for module edgeAgent Jan 16 15:34:48 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:48Z [INFO] - Starting workload API... Jan 16 15:34:49 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:49Z [INFO] - Started Edge runtime module edgeAgent Jan 16 15:34:51 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:51Z [INFO] - <-- GET /trust-bundle?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} Jan 16 15:34:51 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:34:51Z [INFO] - <-- GET /certificates/aziot-edged-trust-bundle?api-version=2020-09-01 {"host": "certd.sock"} Jan 16 15:34:51 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:34:51Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:51 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:51Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:52 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:52Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} Jan 16 15:34:52 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:52Z [INFO] - Querying system info... Jan 16 15:34:52 M7ZZ3298 aziot-edged[835]: kvm Jan 16 15:34:52 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:52Z [INFO] - Successfully queried system info Jan 16 15:34:52 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:52Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:53 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:53Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} Jan 16 15:34:53 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:53Z [INFO] - Querying system info... Jan 16 15:34:53 M7ZZ3298 aziot-edged[835]: kvm Jan 16 15:34:53 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:53Z [INFO] - Successfully queried system info Jan 16 15:34:53 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:53Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:54 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:54Z [INFO] - <-- POST /modules/%24edgeAgent/genid/637783565470929552/sign?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "189"} Jan 16 15:34:54 M7ZZ3298 aziot-identityd[847]: 2023-01-16T15:34:54Z [INFO] - <-- GET /identities/modules/$edgeAgent?api-version=2020-09-01&type=aziot {"host": "identityd.sock"} Jan 16 15:34:54 M7ZZ3298 aziot-tpmd[858]: 2023-01-16T15:34:54Z [INFO] - <-- POST /sign_with_auth_key?api-version=2020-09-01 {"content-type": "application/json", "host": "tpmd.sock", "content-length": "107"} Jan 16 15:34:55 M7ZZ3298 aziot-tpmd[858]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- GET /key/aziot_identityd_master_id?api-version=2020-09-01 {"host": "keyd.sock"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- POST /derivedkey?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "340"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- POST /derivedkey/export?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "736"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- POST /derivedkey?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "340"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- POST /derivedkey/export?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "748"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-identityd[847]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - <-- POST /sign?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "930"} Jan 16 15:34:55 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - Querying system info... Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: kvm Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - Successfully queried system info Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:55 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:55Z [INFO] - <-- POST /modules/%24edgeAgent/genid/637783565470929552/decrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "10991"} Jan 16 15:34:56 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:56Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:34:56 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:56Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:56 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:56Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "11323"} Jan 16 15:34:56 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:56Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:56 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:56Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:56 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:56Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} Jan 16 15:34:56 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:56Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:57 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:57Z [INFO] - <-- POST /modules/%24edgeAgent/genid/637783565470929552/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "10970"} Jan 16 15:34:57 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:57Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:34:57 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:57Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:57 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:57Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "11302"} Jan 16 15:34:57 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:34:57Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:57 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:57Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - <-- POST /modules/edgeHub/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - Stopping module edgeHub... Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - Stopping listener for module edgeHub Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - --> 204 {} Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - <-- POST /modules/edgeHub/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - Starting module edgeHub... Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - Starting new listener for module edgeHub Jan 16 15:34:58 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:58Z [INFO] - Starting workload API... Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - --> 204 {} Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - <-- POST /modules/opcuaPublisher/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - Stopping module opcuaPublisher... Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - Stopping listener for module opcuaPublisher Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - --> 204 {} Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - <-- POST /modules/opcuaPublisher/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - Starting module opcuaPublisher... Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - Starting new listener for module opcuaPublisher Jan 16 15:34:59 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:34:59Z [INFO] - Starting workload API... Jan 16 15:35:00 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:00Z [INFO] - <-- POST /modules/%24edgeHub/genid/637783565470929552/certificate/server?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "69"} Jan 16 15:35:01 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:01Z [INFO] - --> 204 {} Jan 16 15:35:01 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:01Z [INFO] - <-- POST /modules/%24edgeAgent/genid/637783565470929552/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "10970"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- GET /keypair/aziot-edged-ca?api-version=2020-09-01 {"host": "keyd.sock"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:35:01Z [INFO] - <-- POST /certificates?api-version=2020-09-01 {"content-type": "application/json", "host": "certd.sock", "content-length": "1365"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /parameters/algorithm?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "11302"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /parameters/rsa-modulus?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /parameters/rsa-exponent?api-version=2020-09-01 {"content-length": "252", "content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - <-- POST /encrypt?api-version=2020-09-01 {"content-length": "359", "content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:01Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:35:01Z [INFO] - --> 201 {"content-type": "application/json"} Jan 16 15:35:01 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:01Z [INFO] - --> 201 {"content-type": "application/json"} Jan 16 15:35:02 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:02Z [INFO] - <-- GET /trust-bundle?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} Jan 16 15:35:02 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:35:02Z [INFO] - <-- GET /certificates/aziot-edged-trust-bundle?api-version=2020-09-01 {"host": "certd.sock"} Jan 16 15:35:02 M7ZZ3298 aziot-certd[903]: 2023-01-16T15:35:02Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:02 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:02Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - <-- POST /modules/%24edgeHub/genid/637783565470929552/decrypt?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "755"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1083"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - <-- POST /modules/%24edgeHub/genid/637783565470929552/decrypt?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "711"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1039"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - <-- POST /modules/%24edgeHub/genid/637783565470929552/decrypt?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "703"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /key?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "74"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - <-- POST /decrypt?api-version=2020-09-01 {"content-type": "application/json", "host": "keyd.sock", "content-length": "1031"} Jan 16 15:35:04 M7ZZ3298 aziot-keyd[885]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - --> 200 {"content-type": "application/json"} Jan 16 15:35:04 M7ZZ3298 aziot-edged[835]: 2023-01-16T15:35:04Z [INFO] - <-- POST /modules/%24edgeHub/genid/637783565470929552/decrypt?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "719"} ```

edge-agent logs

``` REMARK: the agent should start a lot of edge modules but doesn't do it... <6> 2023-01-16 15:34:46.850 +00:00 [INF] - Disposing module connection object 2023-01-16 15:34:49 Starting Edge Agent 2023-01-16 15:34:49 Changing ownership of storage folder: /iotedge/storage//edgeAgent to 13622 2023-01-16 15:34:49 Changing ownership of backup folder: /tmp/edgeAgent_backup to 13622 2023-01-16 15:34:49 Changing ownership of management socket: /var/run/iotedge/mgmt.sock 2023-01-16 15:34:49 Completed necessary setup. Starting Edge Agent. 2023-01-16 15:34:50.177 +00:00 Edge Agent Main() <6> 2023-01-16 15:34:50.738 +00:00 [INF] - Initializing Edge Agent. <6> 2023-01-16 15:34:51.271 +00:00 [INF] - Version - 1.4.2.61356014 (bb9a26162c4c88b3ef9a50d33632ab78bd4247d6) <6> 2023-01-16 15:34:51.272 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2023-01-16 15:34:51.282 +00:00 [INF] - ModuleUpdateMode: NonBlocking <6> 2023-01-16 15:34:51.444 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false} <6> 2023-01-16 15:34:51.881 +00:00 [INF] - Installing certificates [O=Zededa Inc.:04/10/2023 08:25:33],[CN=Bobst-IoT, OU=IT Infrastructure, O=Bobst Mex S.A., L=Mex, S=Vaud, C=CH:08/17/2036 08:40:51],[CN=BobstRootSHA2:03/06/2042 12:17:11],[CN=Bobst-IoT, OU=IT Infrastructure, O=Bobst Mex S.A., L=Mex, S=Vaud, C=CH:08/17/2036 08:40:51],[CN=BobstRootSHA2:03/06/2042 12:17:11] to Root <6> 2023-01-16 15:34:52.447 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: metrics <6> 2023-01-16 15:34:52.496 +00:00 [INF] - Updating performance metrics every 05m:00s <6> 2023-01-16 15:34:52.514 +00:00 [INF] - Started operation Get system resources <6> 2023-01-16 15:34:52.520 +00:00 [INF] - Collecting metadata metrics <6> 2023-01-16 15:34:52.776 +00:00 [INF] - Set metadata metrics: 1.4.2.61356014 (bb9a26162c4c88b3ef9a50d33632ab78bd4247d6), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"Linux","Architecture":"x86_64","Version":"1.4.2","Provisioning":{"Type":"ProvisioningType","DynamicReprovisioning":false,"AlwaysReprovisionOnStartup":false},"ServerVersion":"20.10.22+azure-1","KernelVersion":"#163-Ubuntu SMP Thu Aug 19 23:31:58 UTC 2021","OperatingSystem":"ubuntu","NumCpus":3,"TotalMemory":2940131328,"Virtualized":"yes"}, True <6> 2023-01-16 15:34:52.843 +00:00 [INF] - Started operation Checkpoint Availability <6> 2023-01-16 15:34:52.853 +00:00 [INF] - Started operation refresh twin config <6> 2023-01-16 15:34:52.904 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only... <6> 2023-01-16 15:34:54.098 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeAgent <6> 2023-01-16 15:34:54.370 +00:00 [INF] - Started operation Metrics Scrape <6> 2023-01-16 15:34:54.371 +00:00 [INF] - Started operation Metrics Upload Scraping frequency: 01:00:00 Upload Frequency: 1.00:00:00 <6> 2023-01-16 15:34:55.524 +00:00 [INF] - Registering request handler UploadModuleLogs <6> 2023-01-16 15:34:55.525 +00:00 [INF] - Registering request handler GetModuleLogs <6> 2023-01-16 15:34:55.525 +00:00 [INF] - Registering request handler UploadSupportBundle <6> 2023-01-16 15:34:55.526 +00:00 [INF] - Registering request handler RestartModule <6> 2023-01-16 15:34:55.938 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only. <6> 2023-01-16 15:34:56.267 +00:00 [INF] - Initialized new module client with subscriptions enabled <6> 2023-01-16 15:34:56.454 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 58 and reported properties version 5307. <6> 2023-01-16 15:34:58.086 +00:00 [INF] - Plan execution started for deployment 58 <6> 2023-01-16 15:34:58.098 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module edgeHub]\n [Start module edgeHub]\n [Saving edgeHub to store]\n)" <6> 2023-01-16 15:34:58.115 +00:00 [INF] - Executing command: "Stop module edgeHub" <6> 2023-01-16 15:34:58.360 +00:00 [INF] - Executing command: "Start module edgeHub" <6> 2023-01-16 15:34:59.777 +00:00 [INF] - Executing command: "Saving edgeHub to store" <6> 2023-01-16 15:34:59.807 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module opcuaPublisher]\n [Start module opcuaPublisher]\n [Saving opcuaPublisher to store]\n)" <6> 2023-01-16 15:34:59.808 +00:00 [INF] - Executing command: "Stop module opcuaPublisher" <6> 2023-01-16 15:34:59.813 +00:00 [INF] - Executing command: "Start module opcuaPublisher" <6> 2023-01-16 15:35:01.060 +00:00 [INF] - Executing command: "Saving opcuaPublisher to store" <6> 2023-01-16 15:35:01.102 +00:00 [INF] - Plan execution ended for deployment 58 <6> 2023-01-16 15:35:02.137 +00:00 [INF] - Updated reported properties <6> 2023-01-16 15:35:07.528 +00:00 [INF] - Updated reported properties ```

edge-hub logs

``` 2023-01-16 15:34:59 Starting Edge Hub 2023-01-16 15:34:59 Starting Edge Hub 2023-01-16 15:34:59 Changing ownership of storage folder: /iotedge/storage//edgeHub to 13623 2023-01-16 15:34:59 Changing ownership of backup folder: /tmp/edgeHub_backup to 13623 2023-01-16 15:34:59.898 +00:00 Edge Hub Main() <6> 2023-01-16 15:35:02.428 +00:00 [INF] - Installing certificates [O=Zededa Inc.:04/10/2023 08:25:33],[CN=Bobst-IoT, OU=IT Infrastructure, O=Bobst Mex S.A., L=Mex, S=Vaud, C=CH:08/17/2036 08:40:51],[CN=BobstRootSHA2:03/06/2042 12:17:11] to Root <6> 2023-01-16 15:35:02.639 +00:00 [INF] - Installing certificates [O=Zededa Inc.:04/10/2023 08:25:33],[CN=Bobst-IoT, OU=IT Infrastructure, O=Bobst Mex S.A., L=Mex, S=Vaud, C=CH:08/17/2036 08:40:51],[CN=BobstRootSHA2:03/06/2042 12:17:11],[CN=Bobst-IoT, OU=IT Infrastructure, O=Bobst Mex S.A., L=Mex, S=Vaud, C=CH:08/17/2036 08:40:51],[CN=BobstRootSHA2:03/06/2042 12:17:11] to Root <6> 2023-01-16 15:35:02.688 +00:00 [INF] - Enabling SSL protocols: Tls12 <6> 2023-01-16 15:35:03.102 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false} <6> 2023-01-16 15:35:04.487 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeHub <6> 2023-01-16 15:35:04.790 +00:00 [INF] - Initializing Edge Hub <6> 2023-01-16 15:35:04.791 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2023-01-16 15:35:04.796 +00:00 [INF] - Version - 1.4.2.61356014 (bb9a26162c4c88b3ef9a50d33632ab78bd4247d6) <6> 2023-01-16 15:35:04.797 +00:00 [INF] - OptimizeForPerformance=True <6> 2023-01-16 15:35:04.797 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2023-01-16 15:35:04.800 +00:00 [INF] - Loaded server certificate with expiration date of "2023-02-15T15:35:01.0000000+00:00" <6> 2023-01-16 15:35:04.831 +00:00 [INF] - Using Asp Net server for metrics <6> 2023-01-16 15:35:05.017 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2023-01-16 15:35:05.021 +00:00 [INF] - Created new message store <6> 2023-01-16 15:35:05.320 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2023-01-16 15:35:06.567 +00:00 [INF] - Add node: M7ZZ3298 <6> 2023-01-16 15:35:06.573 +00:00 [INF] - Add node: M7ZZ3298/$edgeAgent <6> 2023-01-16 15:35:06.574 +00:00 [INF] - Add node: M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:06.574 +00:00 [INF] - Add node: M7ZZ3298/cubePublisher <6> 2023-01-16 15:35:06.574 +00:00 [INF] - Add node: M7ZZ3298/edgeBlob <6> 2023-01-16 15:35:06.574 +00:00 [INF] - Add node: M7ZZ3298/edgeMonitoring <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/edgeMonitoringSystem <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/edgePublisher <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/edgeStorage <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/fileTransfer <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/fileTransferBlob <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/jrmGateway <6> 2023-01-16 15:35:06.575 +00:00 [INF] - Add node: M7ZZ3298/machineEventPublisher <6> 2023-01-16 15:35:06.576 +00:00 [INF] - Add node: M7ZZ3298/notificationPublisher <6> 2023-01-16 15:35:06.576 +00:00 [INF] - Add node: M7ZZ3298/opcuaAdapter <6> 2023-01-16 15:35:06.576 +00:00 [INF] - Add node: M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:06.576 +00:00 [INF] - Add node: M7ZZ3298/recordPublisher <6> 2023-01-16 15:35:06.582 +00:00 [INF] - Created device scope identities cache <6> 2023-01-16 15:35:06.622 +00:00 [INF] - Initialized storing twin manager <6> 2023-01-16 15:35:06.646 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2023-01-16 15:35:06.681 +00:00 [INF] - Updated node: M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:06.682 +00:00 [INF] - Initializing configuration <6> 2023-01-16 15:35:06.772 +00:00 [INF] - New device connection for device M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:06.808 +00:00 [INF] - Client M7ZZ3298/$edgeHub connected to edgeHub, processing existing subscriptions. <6> 2023-01-16 15:35:06.984 +00:00 [INF] - Attempting to connect to IoT Hub for client M7ZZ3298/$edgeHub via AMQP over WebSockets... <6> 2023-01-16 15:35:07.046 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:09.285 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false} <6> 2023-01-16 15:35:09.342 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2023-01-16 15:35:09.495 +00:00 [INF] - Scheduling server certificate renewal for "2023-02-15T15:32:31.0008409Z". <6> 2023-01-16 15:35:10.010 +00:00 [INF] - Not changed node: M7ZZ3298 <6> 2023-01-16 15:35:10.011 +00:00 [INF] - Not changed node: M7ZZ3298/$edgeAgent <6> 2023-01-16 15:35:10.011 +00:00 [INF] - Updated node: M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:10.119 +00:00 [INF] - Service identity for M7ZZ3298/$edgeHub in device scope was updated. <6> 2023-01-16 15:35:10.120 +00:00 [INF] - Not changed node: M7ZZ3298/recordPublisher <6> 2023-01-16 15:35:10.120 +00:00 [INF] - Not changed node: M7ZZ3298/edgeBlob <6> 2023-01-16 15:35:10.121 +00:00 [INF] - Not changed node: M7ZZ3298/machineEventPublisher <6> 2023-01-16 15:35:10.121 +00:00 [INF] - Not changed node: M7ZZ3298/fileTransfer <6> 2023-01-16 15:35:10.121 +00:00 [INF] - Not changed node: M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:10.122 +00:00 [INF] - Not changed node: M7ZZ3298/jrmGateway <6> 2023-01-16 15:35:10.122 +00:00 [INF] - Not changed node: M7ZZ3298/edgeMonitoring <6> 2023-01-16 15:35:10.122 +00:00 [INF] - Not changed node: M7ZZ3298/fileTransferBlob <6> 2023-01-16 15:35:10.123 +00:00 [INF] - Not changed node: M7ZZ3298/notificationPublisher <6> 2023-01-16 15:35:10.123 +00:00 [INF] - Not changed node: M7ZZ3298/cubePublisher <6> 2023-01-16 15:35:10.123 +00:00 [INF] - Not changed node: M7ZZ3298/opcuaAdapter <6> 2023-01-16 15:35:10.123 +00:00 [INF] - Not changed node: M7ZZ3298/edgePublisher <6> 2023-01-16 15:35:10.123 +00:00 [INF] - Not changed node: M7ZZ3298/edgeStorage <6> 2023-01-16 15:35:10.124 +00:00 [INF] - Not changed node: M7ZZ3298/edgeMonitoringSystem <6> 2023-01-16 15:35:10.136 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2023-01-16 15:35:10.623 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2023-01-16 15:35:10.976 +00:00 [INF] - Exiting disconnected state <6> 2023-01-16 15:35:11.038 +00:00 [INF] - Received device connected callback <6> 2023-01-16 15:35:11.179 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2023-01-16 15:35:11.183 +00:00 [INF] - Processing subscriptions for client M7ZZ3298/$edgeHub on device connected to cloud. <6> 2023-01-16 15:35:11.186 +00:00 [INF] - Skipping M7ZZ3298/$edgeHub for subscription processing, as it is currently being processed. <6> 2023-01-16 15:35:11.188 +00:00 [INF] - Skipping cache refresh, waiting 118 seconds until refreshing again. <6> 2023-01-16 15:35:11.226 +00:00 [INF] - Entering connected state <6> 2023-01-16 15:35:11.239 +00:00 [INF] - Cloud connection for M7ZZ3298/$edgeHub is True <6> 2023-01-16 15:35:11.255 +00:00 [INF] - Connection status for M7ZZ3298/$edgeHub changed to ConnectionEstablished <6> 2023-01-16 15:35:11.269 +00:00 [INF] - Client M7ZZ3298/$edgeHub connected to cloud, processing existing subscriptions. <6> 2023-01-16 15:35:11.270 +00:00 [INF] - Skipping M7ZZ3298/$edgeHub for subscription processing, as it is currently being processed. <6> 2023-01-16 15:35:11.277 +00:00 [INF] - Created cloud proxy for client M7ZZ3298/$edgeHub via AMQP over WebSockets, with client operation timeout 20 seconds. <6> 2023-01-16 15:35:11.292 +00:00 [INF] - Initialized cloud proxy 972f1658-beef-4159-aded-480240d715a2 for M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:11.294 +00:00 [INF] - Set the following 16 route(s) in edge hub <6> 2023-01-16 15:35:11.295 +00:00 [INF] - EdgePublisherToUpstream: FROM /messages/modules/edgePublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:11.296 +00:00 [INF] - MachineEventsToUpstream: FROM /messages/modules/machineEventPublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:11.296 +00:00 [INF] - FileTransferToUpstream: FROM /messages/modules/fileTransfer/outputs/* INTO $upstream <6> 2023-01-16 15:35:11.297 +00:00 [INF] - NotificationsToUpstream: FROM /messages/modules/notificationPublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:11.297 +00:00 [INF] - MetricsSystemToUpstream: FROM /messages/modules/edgeMonitoringSystem/* INTO $upstream <6> 2023-01-16 15:35:11.297 +00:00 [INF] - MetricsToUpstream: FROM /messages/modules/edgeMonitoring/* INTO $upstream <6> 2023-01-16 15:35:11.297 +00:00 [INF] - FilterCubeVariables: FROM /messages/modules/cubePublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgePublisher/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - FilterOpcuaVariables: FROM /messages/modules/opcuaAdapter/outputs/variables INTO BrokeredEndpoint("/modules/edgePublisher/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - ConvertOpcuaVariables: FROM /messages/modules/opcuaPublisher/* INTO BrokeredEndpoint("/modules/opcuaAdapter/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - CubeVariablesToStorage: FROM /messages/modules/cubePublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - RecordsToStorage: FROM /messages/modules/recordPublisher/outputs/records INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - OpcuaVariablesToStorage: FROM /messages/modules/opcuaAdapter/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - NotificationsToStorage: FROM /messages/modules/notificationPublisher/outputs/faults INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - MachineEventsToStorage: FROM /messages/modules/machineEventPublisher/outputs/event INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - MachineVariablesToStorage: FROM /messages/modules/machineEventPublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.297 +00:00 [INF] - MachineNotificationsToStorage: FROM /messages/modules/machineEventPublisher/outputs/faults INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:11.298 +00:00 [INF] - Created cloud connection for client M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:11.303 +00:00 [INF] - Updated message store TTL to 1209600 seconds <6> 2023-01-16 15:35:11.305 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2023-01-16 15:35:11.511 +00:00 [INF] - Started operation Get EdgeHub config <6> 2023-01-16 15:35:11.512 +00:00 [INF] - Initialized edge hub configuration <6> 2023-01-16 15:35:11.516 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2023-01-16 15:35:11.524 +00:00 [INF] - Starting MQTT head <6> 2023-01-16 15:35:11.694 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2023-01-16 15:35:11.779 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:11.800 +00:00 [INF] - Updated reported properties for M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:11.917 +00:00 [INF] - Starting AMQP head <6> 2023-01-16 15:35:11.962 +00:00 [INF] - Started MQTT head <6> 2023-01-16 15:35:12.098 +00:00 [INF] - Started AMQP head <6> 2023-01-16 15:35:12.109 +00:00 [INF] - Starting HTTP head <6> 2023-01-16 15:35:12.295 +00:00 [INF] - Obtained edge hub config from module twin <6> 2023-01-16 15:35:12.364 +00:00 [INF] - Set the following 16 route(s) in edge hub <6> 2023-01-16 15:35:12.365 +00:00 [INF] - EdgePublisherToUpstream: FROM /messages/modules/edgePublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - MachineEventsToUpstream: FROM /messages/modules/machineEventPublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - FileTransferToUpstream: FROM /messages/modules/fileTransfer/outputs/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - NotificationsToUpstream: FROM /messages/modules/notificationPublisher/outputs/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - MetricsSystemToUpstream: FROM /messages/modules/edgeMonitoringSystem/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - MetricsToUpstream: FROM /messages/modules/edgeMonitoring/* INTO $upstream <6> 2023-01-16 15:35:12.365 +00:00 [INF] - FilterCubeVariables: FROM /messages/modules/cubePublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgePublisher/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - FilterOpcuaVariables: FROM /messages/modules/opcuaAdapter/outputs/variables INTO BrokeredEndpoint("/modules/edgePublisher/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - ConvertOpcuaVariables: FROM /messages/modules/opcuaPublisher/* INTO BrokeredEndpoint("/modules/opcuaAdapter/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - CubeVariablesToStorage: FROM /messages/modules/cubePublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - RecordsToStorage: FROM /messages/modules/recordPublisher/outputs/records INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - OpcuaVariablesToStorage: FROM /messages/modules/opcuaAdapter/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.365 +00:00 [INF] - NotificationsToStorage: FROM /messages/modules/notificationPublisher/outputs/faults INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.366 +00:00 [INF] - MachineEventsToStorage: FROM /messages/modules/machineEventPublisher/outputs/event INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.366 +00:00 [INF] - MachineVariablesToStorage: FROM /messages/modules/machineEventPublisher/outputs/variables INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.366 +00:00 [INF] - MachineNotificationsToStorage: FROM /messages/modules/machineEventPublisher/outputs/faults INTO BrokeredEndpoint("/modules/edgeStorage/inputs/input") <6> 2023-01-16 15:35:12.366 +00:00 [INF] - Updated message store TTL to 1209600 seconds <6> 2023-01-16 15:35:12.366 +00:00 [INF] - Updated the edge hub store and forward configuration <4> 2023-01-16 15:35:12.813 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined via IConfiguration and/or UseKestrel() instead. <6> 2023-01-16 15:35:12.917 +00:00 [INF] - Started HTTP head <6> 2023-01-16 15:35:13.650 +00:00 [INF] - Client M7ZZ3298/opcuaPublisher in device scope authenticated locally. <6> 2023-01-16 15:35:13.681 +00:00 [INF] - Successfully generated identity for clientId M7ZZ3298/opcuaPublisher and username M7ZZ3298/M7ZZ3298/opcuaPublisher/?api-version=2020-09-30&DeviceClientType=.NET%2F1.38.0%20%28.NET%20Core%203.1.23%3B%20Linux%204.15.0-156-generic%20%23163-Ubuntu%20SMP%20Thu%20Aug%2019%2023%3A31%3A58%20UTC%202021%3B%20X64%29%20OpcPublisher_2.8.2.1 <6> 2023-01-16 15:35:13.697 +00:00 [INF] - "ClientAuthenticated, M7ZZ3298/opcuaPublisher, 2140dbbd" <6> 2023-01-16 15:35:13.799 +00:00 [INF] - New device connection for device M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:13.802 +00:00 [INF] - Client M7ZZ3298/opcuaPublisher connected to edgeHub, processing existing subscriptions. <6> 2023-01-16 15:35:13.812 +00:00 [INF] - Attempting to connect to IoT Hub for client M7ZZ3298/opcuaPublisher via AMQP over WebSockets... <6> 2023-01-16 15:35:13.884 +00:00 [INF] - Bind device proxy for device M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:13.886 +00:00 [INF] - Binding message channel for device Id M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:13.911 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:13.983 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, DesiredPropertyUpdates for client M7ZZ3298/opcuaPublisher. <6> 2023-01-16 15:35:14.010 +00:00 [INF] - Cloud connection for M7ZZ3298/opcuaPublisher is True <6> 2023-01-16 15:35:14.010 +00:00 [INF] - Connection status for M7ZZ3298/opcuaPublisher changed to ConnectionEstablished <6> 2023-01-16 15:35:14.010 +00:00 [INF] - Client M7ZZ3298/opcuaPublisher connected to cloud, processing existing subscriptions. <6> 2023-01-16 15:35:14.010 +00:00 [INF] - Skipping M7ZZ3298/opcuaPublisher for subscription processing, as it is currently being processed. <6> 2023-01-16 15:35:14.010 +00:00 [INF] - Created cloud proxy for client M7ZZ3298/opcuaPublisher via AMQP over WebSockets, with client operation timeout 20 seconds. <6> 2023-01-16 15:35:14.011 +00:00 [INF] - Initialized cloud proxy d4d97587-5930-46f6-b062-6beff491b236 for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.011 +00:00 [INF] - Created cloud connection for client M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.021 +00:00 [INF] - Set subscriptions from session state for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.084 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.084 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.084 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.115 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, DesiredPropertyUpdates for client M7ZZ3298/opcuaPublisher. <6> 2023-01-16 15:35:14.116 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:14.118 +00:00 [INF] - Set subscriptions from session state for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:16.283 +00:00 [INF] - Processing subscriptions TwinResponse, Methods, DesiredPropertyUpdates for client M7ZZ3298/opcuaPublisher. <6> 2023-01-16 15:35:16.287 +00:00 [INF] - Processing pending subscriptions for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:16.293 +00:00 [INF] - Set subscriptions from session state for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:35:17.536 +00:00 [INF] - Updated reported properties for M7ZZ3298/$edgeHub <6> 2023-01-16 15:35:17.941 +00:00 [INF] - Updated reported properties for M7ZZ3298/opcuaPublisher <6> 2023-01-16 15:40:09.463 +00:00 [INF] - Entering periodic task to reauthenticate connected clients ```

Additional Information

Please provide any additional information that may be helpful in understanding the issue.

lfitchett commented 1 year ago

@giovannimele If the certificates are changed, edge must be restarted. The reason you are having to clean docker is that edgeAgent has a MaxRestart for modules. What is likely happening is that the modules are failing enough times before edge is restarted that the count is reached. This can be solved in 2 steps:

Include sudo iotedge system restart in the job that updates the certs. This should prevent the modules from failing in the first place and the restart limit should not be hit.
(Optional) Set the edgeAgent environment variable MaxRestartCount to 4,294,967,295 (max value of u32). This will ensure edgehub always restarts modules.

giovannimele commented 1 year ago

@lfitchett thx for your answer. In fact, this is what is done (iotedge system restart).

Maybe I'll give you more detailed explanation:

Our edge devices are running in VMs on an EVE hypervisor.

When we want to update the iotedge certificate, we 'purge' the VM, i.e we rollback all changes that were made to the original image. All is cleaned except the folder /var/lib/aziot and all docker containers' data (as we don't want to pull again the containers and loose the data stored on the external volumes)), the edgeHub storage is cleaned, but not the edgeAgent one. Here is the reference on a ticket we opened about problem with edgeHub and the reason we don't clean everything during the purge: https://github.com/Azure/iotedge/issues/6736.

Once the purge is done, when the VM restarts, it execute the cloud-init. The cloud init does the following steps:

downloads our root CA
generates the iotedge certificate with the root CA
restarts the iotedge service

This was working well with iotedge 1.2. After migration to iotedge 1.4, this stopped working. In fact, we see that the docker modules are starting, trying to connect to the edheHub and get the TLS exception. It is like if some certificate information was stored in the container data and doesn't match the new certificate....

The only way to solve this is to clean the containers using the docker system prune -a and let the agent pull again all modules. This can be a problem with some of our customers with very low bandwidth as the edge device stays offline for a very long period (and may fall in the described edgeAgent MaxRestart problem)

lfitchett commented 1 year ago

The only way to solve this is to clean the containers using the docker system prune -a and let the agent pull again all modules. This can be a problem with some of our customers with very low bandwidth as the edge device stays offline for a very long period (and may fall in the described edgeAgent MaxRestart problem)

Do you need to delete the module images? Have you tried only deleting the container instance using docker rm? This should clear all data without requiring a re-download.

Additionally, it is strange that removing the images would be required in the first place. Is there a reason you rollback all the changes to the VM image instead of simply replacing the existing cert?

giovannimele commented 1 year ago

@lfitchett thx for the answer. I'll try the docker rm, but I think I tried it during all my test to unblock the situation. I've a machine still with the problem and I'll keep you informed of the result.

About why we do the purge is because it is the only way we can contact the edge. As it may be down, we use a dedicated web app to trigger a purge of the VM.... As soon as the hypervisor starts, it contact the web site and will purge the VM image, trigerring the cloud init and updating the certificate... yes, it is complicated...

giovannimele commented 1 year ago

@lfitchett Tried the docker rm, but unfortunately, all modules except edgeAgent and edgeHub are not starting anymore. What I did was a docker rm on the edgeAgent, edgeHub and some of my modules (after having stopped iotedge). Then I restarted the iotedge. The edgeHub and the edgeAgent restarted, but not the other modules

vchthakur commented 1 year ago

May be you can try by removing all containers and volumes:

sudo iotedge system stop docker system prune --all --volumes

Review the warning that the command issues and confirm with y when ready. and then re-apply the config sudo iotedge config apply

giovannimele commented 1 year ago

@vchthakur this is already what we do with the docker system prune -a -f as a workaround (we stop the iotedge before and restart it after the prune cmd). The problem with this is that all containers and the images are deleted and need to be downloaded again...

micahl commented 1 year ago

@giovannimele other than edgeAgent and edgeHub are the other modules custom modules you own and if so, which version of the IoT device SDK do they use (version and language)? If .NET are they targeting .NET 6 or something earlier? Only asking because I've seen an identical error appear for a module that was using a very old version of the .NET device SDK that was no longer supported.

giovannimele commented 1 year ago

@micahl we are using .Net 3.1. We have to migrate them, but it has not be done yet. Do you think it may be the cause of the problem?

micahl commented 1 year ago

@giovannimele in the case I saw the module was targeting .NET 2.1, used v1.26 of the IoT device SDK, and was using Ubuntu 16.04 as the base OS for the container. Since the code wasn't very complex the migration (in this case) didn't involve any changes to the code. Just by bumping the target to .NET 6, picking up a more recent device SDK (v1.36 or 1.41), and changing the base OS for the container to Ubuntu 20.04 and the error disappeared. I don't know which one (or combination) of those 3 fixed it, but they all needed to be updated anyway. If you can, I'd suggest trying a simple test to ensure everything is on the latest and if the error still occurs.

giovannimele commented 1 year ago

@lfitchett except the update of the .NET version in our modules, any other suggestion, hint, idea we could test? Were you able to reproduce the problem?

giovannimele commented 1 year ago

@micahl we updated all our modules to ,net 7 and also updated all azure modules we are using like azure-blob-storage (1.4.3) and azureiotedge-metrics-collector (1.1.1). The docker container used is Ubuntu 22.04 (7.0-jammy), but we are still running on Ubuntu 18.04 on the host as we cannot change so easily.

After the changes, we reapplied several times the certificate generation procedure (by purging the VM image) and we noticed a slight amelioration: now the freeze of the modules is random... once it works, once it doesn't... random.

I collected the logs from one of our modules and one from an Azure module:

azureiotedge-metrics-collector

[2023-02-02 14:52:46.599 INF] Trying to initialize module client using transport type [Amqp_Tcp_Only]
[2023-02-02 14:52:50.783 ERR] Error occurred during metrics collection setup.
System.Security.Authentication.AuthenticationException: TLS authentication error.
 ---> System.Security.Authentication.AuthenticationException: The remote certificate was rejected by the provided RemoteCertificateValidationCallback.
   at System.Net.Security.SslStream.SendAuthResetSignal(ProtocolToken message, ExceptionDispatchInfo exception)
   at System.Net.Security.SslStream.CompleteHandshake(SslAuthenticationOptions sslAuthenticationOptions)
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](TIOAdapter adapter, Boolean receiveFirst, Byte[] reAuthenticationData, Boolean isApm)
   at System.Threading.Tasks.TaskToApm.End(IAsyncResult asyncResult)
   at System.Net.Security.SslStream.EndAuthenticateAsClient(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.Transport.TlsTransport.HandleOpenComplete(IAsyncResult result, Boolean syncComplete)

custom module .NET 7

<6> 2023-02-02 14:54:04.740 +00:00 [INF] Building EdgeModule Client
Unhandled exception. System.AggregateException: One or more errors occurred. (TLS authentication error.)
 ---> System.Security.Authentication.AuthenticationException: TLS authentication error.
 ---> System.AggregateException: One or more errors occurred. (The remote certificate is invalid because of errors in the certificate chain: NotSignatureValid)
 ---> System.Security.Authentication.AuthenticationException: The remote certificate is invalid because of errors in the certificate chain: NotSignatureValid
   at System.Net.Security.SslStream.SendAuthResetSignal(ProtocolToken message, ExceptionDispatchInfo exception)
   at System.Net.Security.SslStream.CompleteHandshake(SslAuthenticationOptions sslAuthenticationOptions)
   at System.Net.Security.SslStream.ForceAuthenticationAsync[TIOAdapter](Boolean receiveFirst, Byte[] reAuthenticationData, CancellationToken cancellationToken)

It visibly complains about the certification chain... but why does it works time to time? Is there a way to see the certificate the module is using? How can we debug the certificate validation?

giovannimele commented 1 year ago

@lfitchett @micahl any news on this issue on your side? Were you able to reproduce the problem? Do you need more logs from my side?

micahl commented 1 year ago

@giovannimele I think we'll need more info. Can you create a microsoft support ticket via the Azure portal?

And then ...

github-actions[bot] commented 1 year ago

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

Azure / iotedge