iotedge: Edge modules fail to connect on EdgeHub after certificate update
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.
About this issue
- Original URL
- State: open
- Created a year ago
- Comments: 15 (5 by maintainers)
@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:
sudo iotedge system restartin 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.