Azure / iotedge

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

1.4.2 System modules, edgeAgent and/or edgeHub, fails to start with the error `System.Security.Cryptography.CryptographicException: The X509 certificate could not be added to the store.`. #6855

Open FinitelyFailed opened 1 year ago

FinitelyFailed commented 1 year ago

System modules, edgeAgent and/or edgeHub, fails to start with the error System.Security.Cryptography.CryptographicException: The X509 certificate could not be added to the store..

This happens to devices we have in production, we managed to run iotedge support-bundle to get the collection of logs. But had to reinstall the system module after that as the device is in a production environment.

Expected Behavior

The system modules should never fail like this.

Current Behavior

System modules, edgeAgent and/or edgeHub, fails to start with the error System.Security.Cryptography.CryptographicException: The X509 certificate could not be added to the store.. This seems to happen at random.

Stopping the iotedge system (iotedge system stop), uninstalling the container and image of the failed system module via docker and restarting the iotedge system (iotedge system restart) reinstalls the failed system module, which makes it work as expected.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. Run the system for a while.
  2. One of the system modules fails to start.

Context (Environment)

Output of iotedge check

Click here ``` ```

Device Information

Runtime Versions

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

Logs

aziot-edged logs ``` -- Logs begin at Mon 2023-01-16 13:17:01 CET, end at Mon 2023-01-16 14:48:24 CET. -- jan 16 13:36:48 edge-dev-pi systemd[1]: Started Azure IoT Edge daemon. jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Starting Azure IoT Edge Daemon jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Version - 1.4.2 jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Obtaining Edge device provisioning data... jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Device is c4c7bb59-0977-4dc8-9c2e-f82cf5410e45-edge on syscomiotI.azure-devices.net jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Initializing module runtime... jan 16 13:36:48 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:48Z [INFO] - Using runtime network id azure-iot-edge jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Successfully initialized module runtime jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Using existing Edge CA certificate jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Certificate aziot-edged-ca will be auto-renewed. Next renewal at 2023-01-26T07:26:22+00:00. jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping all modules... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module A... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module B... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module C... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module D... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module E... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module F... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module G... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module H... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module I... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping module J... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - All modules stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Detecting if device information has changed... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Device information has not changed jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting management API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module A jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module B jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module C jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module D jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module E jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module F jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module G jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module H jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module I jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module J jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module A jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module B jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module C jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module D jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module E jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module F jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting watchdog with 60 second period... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module G jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module H jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module I jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Stopping listener for module J jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Workload API stopped jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting image garbage collection task... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Watchdog checking Edge runtime status jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Edge runtime status is failed, starting module now... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting module J... jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting new listener for module J jan 16 13:36:49 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:49Z [INFO] - Starting workload API... jan 16 13:36:51 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:51Z [INFO] - Started Edge runtime module J jan 16 13:36:53 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:53Z [INFO] - <-- GET /trust-bundle?api-version=2020-07-07 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:36:53 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:53Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - Querying system info... jan 16 13:36:54 edge-dev-pi aziot-edged[924]: none jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - Successfully queried system info jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - Querying system info... jan 16 13:36:54 edge-dev-pi aziot-edged[924]: none jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - Successfully queried system info jan 16 13:36:54 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:54Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:57 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:57Z [INFO] - <-- POST /modules/%24J/genid/637987505423400772/sign?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "217"} jan 16 13:36:57 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:57Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - <-- GET /systeminfo?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - Querying system info... jan 16 13:36:58 edge-dev-pi aziot-edged[924]: none jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - Successfully queried system info jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - <-- POST /modules/%24J/genid/637987505423400772/decrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "6155"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:36:58 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:58Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - <-- POST /modules/%24J/genid/637987505423400772/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "6134"} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - <-- POST /modules/F/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - Stopping module F... jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - Stopping listener for module F jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - --> 204 {} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - <-- POST /modules/F/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - Starting module F... jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - Starting new listener for module F jan 16 13:36:59 edge-dev-pi aziot-edged[924]: 2023-01-16T12:36:59Z [INFO] - Starting workload API... jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - --> 204 {} jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - <-- POST /modules/B/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - Stopping module B... jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - Stopping listener for module B jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - --> 204 {} jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - <-- POST /modules/B/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - Starting module B... jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - Starting new listener for module B jan 16 13:37:00 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:00Z [INFO] - Starting workload API... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/D/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping module D... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping listener for module D jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/D/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting module D... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting new listener for module D jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting workload API... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/A/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping module A... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping listener for module A jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/A/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting module A... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting new listener for module A jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting workload API... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/E/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping module E... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Stopping listener for module E jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - --> 204 {} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - <-- POST /modules/E/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting module E... jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting new listener for module E jan 16 13:37:01 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:01Z [INFO] - Starting workload API... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - --> 204 {} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - <-- POST /modules/H/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Stopping module H... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Stopping listener for module H jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - --> 204 {} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - <-- POST /modules/H/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting module H... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting new listener for module H jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting workload API... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - --> 204 {} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - <-- POST /modules/G/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Stopping module G... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Stopping listener for module G jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - --> 204 {} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - <-- POST /modules/G/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting module G... jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting new listener for module G jan 16 13:37:02 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:02Z [INFO] - Starting workload API... jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - --> 204 {} jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - <-- POST /modules/C/stop?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - Stopping module C... jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - Stopping listener for module C jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - --> 204 {} jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - <-- POST /modules/C/start?api-version=2022-08-03 {"host": "mgmt.sock:80", "connection": "close", "content-type": "application/json; charset=utf-8", "content-length": "0"} jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - Starting module C... jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - Starting new listener for module C jan 16 13:37:03 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:03Z [INFO] - Starting workload API... jan 16 13:37:04 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:04Z [INFO] - --> 204 {} jan 16 13:37:04 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:04Z [INFO] - <-- POST /modules/%24J/genid/637987505423400772/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "6134"} jan 16 13:37:04 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:04Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:04 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:04Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:04 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:04Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:06 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:06Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:07 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:07Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:07 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:07Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:07 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:07Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:07 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:07Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:08 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:08Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:08 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:08Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:09 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:09Z [INFO] - <-- GET /trust-bundle?api-version=2018-06-28 {"accept": "application/json", "host": "workload.sock:80", "connection": "close"} jan 16 13:37:09 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:09Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:37:10 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:10Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:37:10 edge-dev-pi aziot-edged[924]: 2023-01-16T12:37:10Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:57:33 edge-dev-pi aziot-edged[924]: 2023-01-16T12:57:33Z [INFO] - <-- GET /modules?api-version=2022-08-03 {"accept": "application/json", "host": "mgmt.sock:80", "connection": "close"} jan 16 13:57:33 edge-dev-pi aziot-edged[924]: 2023-01-16T12:57:33Z [INFO] - --> 200 {"content-type": "application/json"} jan 16 13:57:33 edge-dev-pi aziot-edged[924]: 2023-01-16T12:57:33Z [INFO] - <-- POST /modules/%24J/genid/637987505423400772/encrypt?api-version=2022-08-03 {"accept": "application/json", "host": "workload.sock:80", "connection": "close", "content-type": "application/json", "content-length": "6134"} ```
edge-agent logs ``` 2023-01-16 10:51:59 Starting Edge Agent 2023-01-16 10:51:59 Creating UID 1000 as Juser 2023-01-16 10:51:59 Changing ownership of storage folder: /iotedge/storage//J to 1000 2023-01-16 10:51:59 Creating backup folder: /tmp/J_backup 2023-01-16 10:51:59 Changing ownership of management socket: /var/run/iotedge/mgmt.sock 2023-01-16 10:51:59 Completed necessary setup. Starting Edge Agent. 2023-01-16 10:51:59.546 +00:00 Edge Agent Main() <6> 2023-01-16 10:52:00.130 +00:00 [INF] - Initializing Edge Agent. <6> 2023-01-16 10:52:00.608 +00:00 [INF] - Version - 1.4.2.61356014 (bb9a26162c4c88b3ef9a50d33632ab78bd4247d6) <6> 2023-01-16 10:52:00.610 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2023-01-16 10:52:00.618 +00:00 [INF] - ModuleUpdateMode: NonBlocking <6> 2023-01-16 10:52:00.754 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false} <6> 2023-01-16 10:52:01.073 +00:00 [INF] - Installing certificates [CN=iotedged workload ca edge-dev-pi:02/13/2023 07:26:22] to Root <6> 2023-01-16 10:52:01.537 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: metrics <6> 2023-01-16 10:52:01.583 +00:00 [INF] - Updating performance metrics every 05m:00s <6> 2023-01-16 10:52:01.600 +00:00 [INF] - Started operation Get system resources <6> 2023-01-16 10:52:01.605 +00:00 [INF] - Collecting metadata metrics <6> 2023-01-16 10:52:01.845 +00:00 [INF] - Set metadata metrics: 1.4.2.61356014 (bb9a26162c4c88b3ef9a50d33632ab78bd4247d6), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"Linux","Architecture":"arm","Version":"1.4.2","Provisioning":{"Type":"ProvisioningType","DynamicReprovisioning":false,"AlwaysReprovisionOnStartup":false},"ServerVersion":"20.10.21+azure-1","KernelVersion":"#1496 SMP Wed Dec 1 15:58:56 GMT 2021","OperatingSystem":"raspbian","NumCpus":4,"TotalMemory":4121808896,"Virtualized":"no"}, True <6> 2023-01-16 10:52:01.901 +00:00 [INF] - Started operation Checkpoint Availability <6> 2023-01-16 10:52:01.910 +00:00 [INF] - Started operation refresh twin config <6> 2023-01-16 10:52:01.964 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only... <6> 2023-01-16 10:52:03.153 +00:00 [INF] - Created persistent store at /iotedge/storage/J <6> 2023-01-16 10:52:03.388 +00:00 [INF] - Started operation Metrics Scrape <6> 2023-01-16 10:52:03.389 +00:00 [INF] - Started operation Metrics Upload Scraping frequency: 01:00:00 Upload Frequency: 1.00:00:00 <6> 2023-01-16 10:52:04.066 +00:00 [INF] - Registering request handler UploadModuleLogs <6> 2023-01-16 10:52:04.066 +00:00 [INF] - Registering request handler GetModuleLogs <6> 2023-01-16 10:52:04.067 +00:00 [INF] - Registering request handler UploadSupportBundle <6> 2023-01-16 10:52:04.067 +00:00 [INF] - Registering request handler RestartModule <6> 2023-01-16 10:52:04.538 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only. <6> 2023-01-16 10:52:04.862 +00:00 [INF] - Initialized new module client with subscriptions enabled <6> 2023-01-16 10:52:05.009 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 21 and reported properties version 1461. <6> 2023-01-16 10:52:11.316 +00:00 [INF] - Plan execution started for deployment 21 <6> 2023-01-16 10:52:11.324 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.334 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.334 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.335 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.335 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.335 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.335 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.335 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.336 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 10:52:11.366 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare module I]\n [Create module I]\n)]\n [Start module I]\n)" <6> 2023-01-16 10:52:11.372 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare module I]\n [Create module I]\n)" at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 135 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 147 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 245 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 214 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 143 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 158 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 61 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 61 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 91 --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.<>c.b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 129 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 162 <4> 2023-01-16 11:14:26.499 +00:00 [WRN] - Reconcile failed because of the an exception System.AggregateException: One or more errors occurred. (The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.) ---> System.Threading.Tasks.TaskCanceledException: The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing. ---> System.TimeoutException: The operation was canceled. ---> System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at System.Threading.CancellationToken.ThrowIfCancellationRequested() at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken) at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask) at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62 at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158 at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69 at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48 at System.Net.Http.HttpClient.g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) --- End of inner exception stack trace --- --- End of inner exception stack trace --- at System.Net.Http.HttpClient.HandleFailure(Exception e, Boolean telemetryStarted, HttpResponseMessage response, CancellationTokenSource cts, CancellationToken cancellationToken, CancellationTokenSource pendingRequestsCts) at System.Net.Http.HttpClient.g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/generatedCode/EdgeletHttpClient.cs:line 636 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 137 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 135 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 147 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 245 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 214 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 143 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 158 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 61 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 61 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 91 --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.<>c.b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 129 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 162 at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 174 <6> 2023-01-16 11:14:26.990 +00:00 [INF] - Updated reported properties <6> 2023-01-16 11:14:33.590 +00:00 [INF] - Module 'I' scheduled to restart after 20s (17s left). <6> 2023-01-16 11:14:33.594 +00:00 [INF] - Plan execution started for deployment 21 <6> 2023-01-16 11:14:33.596 +00:00 [INF] - Executing command: "[Null]" <6> 2023-01-16 11:14:33.600 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare module A]\n [Create module A]\n)]\n [Start module A]\n)" <6> 2023-01-16 11:14:33.600 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare module A]\n [Create module A]\n)" <6> 2023-01-16 11:14:35.595 +00:00 [INF] - Executing command: "Start module A" <6> 2023-01-16 11:14:35.871 +00:00 [INF] - Plan execution ended for deployment 21 <6> 2023-01-16 11:14:36.132 +00:00 [INF] - Updated reported properties <6> 2023-01-16 11:14:41.199 +00:00 [INF] - Module 'I' scheduled to restart after 20s (09s left). <6> 2023-01-16 11:14:41.411 +00:00 [INF] - Updated reported properties <6> 2023-01-16 11:14:46.540 +00:00 [INF] - Module 'I' scheduled to restart after 20s (04s left). <6> 2023-01-16 11:14:51.627 +00:00 [INF] - Plan execution started for deployment 21 <6> 2023-01-16 11:14:51.627 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module I]\n [Start module I]\n [Saving I to store]\n)" <6> 2023-01-16 11:14:51.628 +00:00 [INF] - Executing command: "Stop module I" <6> 2023-01-16 11:14:51.632 +00:00 [INF] - Executing command: "Start module I" <6> 2023-01-16 11:14:52.796 +00:00 [INF] - Executing command: "Saving I to store" <6> 2023-01-16 11:14:52.798 +00:00 [INF] - Plan execution ended for deployment 21 <6> 2023-01-16 11:14:58.028 +00:00 [INF] - Module 'I' scheduled to restart after 40s (38s left). <6> 2023-01-16 11:14:58.235 +00:00 [INF] - Updated reported properties <6> 2023-01-16 11:15:03.359 +00:00 [INF] - Module 'I' scheduled to restart after 40s (33s left). <6> 2023-01-16 11:15:08.481 +00:00 [INF] - Module 'I' scheduled to restart after 40s (27s left). <6> 2023-01-16 11:15:13.595 +00:00 [INF] - Module 'I' scheduled to restart after 40s (22s left). <6> 2023-01-16 11:15:18.720 +00:00 [INF] - Module 'I' scheduled to restart after 40s (17s left). <6> 2023-01-16 11:15:23.847 +00:00 [INF] - Module 'I' scheduled to restart after 40s (12s left). <6> 2023-01-16 11:15:28.994 +00:00 [INF] - Module 'I' scheduled to restart after 40s (07s left). <6> 2023-01-16 11:15:34.111 +00:00 [INF] - Module 'I' scheduled to restart after 40s (02s left). <6> 2023-01-16 11:15:39.233 +00:00 [INF] - Plan execution started for deployment 21 <6> 2023-01-16 11:15:39.234 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module I]\n [Start module I]\n [Saving I to store]\n)" ```
edge-hub logs ``` 2023-01-16 11:14:26 Starting Edge Hub 2023-01-16 11:14:26 Starting Edge Hub 2023-01-16 11:14:26 Changing ownership of storage folder: /iotedge/storage//edgeHub to 1000 2023-01-16 11:14:26 Creating backup folder: /tmp/edgeHub_backup 2023-01-16 11:14:26.682 +00:00 Edge Hub Main() <6> 2023-01-16 11:14:30.581 +00:00 [INF] - Installing certificates [CN=iotedged workload ca edge-dev-pi:02/13/2023 07:26:22] to Root <3> 2023-01-16 11:14:30.647 +00:00 [ERR] - Stopping with exception System.Security.Cryptography.CryptographicException: The X509 certificate could not be added to the store. ---> System.UnauthorizedAccessException: Access to the path '/home/edgehubuser/.dotnet/corefx/cryptography/x509stores/root' is denied. ---> System.IO.IOException: Permission denied --- End of inner exception stack trace --- at System.IO.FileSystem.CreateDirectory(String fullPath) at System.IO.Directory.CreateDirectory(String path) at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.AddCertToStore(ICertificatePal certPal) at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.Add(ICertificatePal certPal) --- End of inner exception stack trace --- at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.Add(ICertificatePal certPal) at System.Security.Cryptography.X509Certificates.X509Store.Add(X509Certificate2 certificate) at Microsoft.Azure.Devices.Edge.Util.CertificateHelper.InstallCertificates(IEnumerable`1 certificateChain, ILogger logger) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs:line 226 at Microsoft.Azure.Devices.Edge.Hub.Service.EdgeHubCertificates.LoadAsync(IConfigurationRoot configuration, ILogger logger) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs:line 95 at Microsoft.Azure.Devices.Edge.Hub.Service.Program.MainAsync(IConfigurationRoot configuration) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs:line 58 Unhandled exception. System.AggregateException: One or more errors occurred. (The X509 certificate could not be added to the store.) ---> System.Security.Cryptography.CryptographicException: The X509 certificate could not be added to the store. ---> System.UnauthorizedAccessException: Access to the path '/home/edgehubuser/.dotnet/corefx/cryptography/x509stores/root' is denied. ---> System.IO.IOException: Permission denied --- End of inner exception stack trace --- at System.IO.FileSystem.CreateDirectory(String fullPath) at System.IO.Directory.CreateDirectory(String path) at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.AddCertToStore(ICertificatePal certPal) at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.Add(ICertificatePal certPal) --- End of inner exception stack trace --- at Internal.Cryptography.Pal.DirectoryBasedStoreProvider.Add(ICertificatePal certPal) at System.Security.Cryptography.X509Certificates.X509Store.Add(X509Certificate2 certificate) at Microsoft.Azure.Devices.Edge.Util.CertificateHelper.InstallCertificates(IEnumerable`1 certificateChain, ILogger logger) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/CertificateHelper.cs:line 226 at Microsoft.Azure.Devices.Edge.Hub.Service.EdgeHubCertificates.LoadAsync(IConfigurationRoot configuration, ILogger logger) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/EdgeHubCertificates.cs:line 95 at Microsoft.Azure.Devices.Edge.Hub.Service.Program.MainAsync(IConfigurationRoot configuration) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs:line 58 --- End of inner exception stack trace --- at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification) at System.Threading.Tasks.Task`1.get_Result() at Microsoft.Azure.Devices.Edge.Hub.Service.Program.Main() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Service/Program.cs:line 35 ```

Additional Information

We have upgraded from 1.2.x to 1.4.2 on our devices. Under 1.2.x we had no issue like this.

lfitchett commented 1 year ago

@FinitelyFailed Can you please provide some additional information:

The relevant error is: System.UnauthorizedAccessException: Access to the path '/home/edgehubuser/.dotnet/corefx/cryptography/x509stores/root' is denied.

FinitelyFailed commented 1 year ago

@lfitchett thanks for your response.

As I state above I reinstalled edgeHub on the faulty device as it is in production, and I needed to get it working as fast as possible. At the moment I do not have access to it. The problem seems to appear at random, a device that worked fine one day get this error the next day.

I have included the logs that sudo iotedge support-bundle collects.

This is the output from sudo iotedge check --verbose from an other device running the same image, the OS configuration is identical to the faulty one:

pi@edge-dev-pi:~ $ sudo iotedge check --verbose

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 - OK
√ preloaded certificates are valid - OK
√ keyd is running - OK
√ certd 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 - OK
√ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with iothub MQTT port - 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.
        caused by: 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.
        caused by: 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
√ Agent image is valid and can be pulled from upstream - OK
√ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK

Connectivity checks
-------------------
√ container on the default network can connect to upstream AMQP port - OK
√ container on the default network can connect to upstream HTTPS / WebSockets port - OK
√ container on the default network can connect to upstream MQTT port - OK
    skipping because of not required in this configuration
√ container on the IoT Edge module network can connect to upstream AMQP port - OK
√ container on the IoT Edge module network can connect to upstream HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to upstream MQTT port - OK
    skipping because of not required in this configuration
33 check(s) succeeded.
2 check(s) raised warnings.
2 check(s) were skipped due to errors from other checks.

The the edgeHubs storage is mounted on the host. And I think the iotedge user have full permissions to the mounted folder. This is from an other device, running the same image and OS config:

pi@edge-dev-pi:~ $ ls -lha /etc/aziot/
total 68K
drwxr-xr-x  8 root root 4.0K Dec  6 13:22 .
drwxr-xr-x 96 root root 4.0K Jan 18 14:30 ..
drwxr-xr-x  3 root root 4.0K Nov  2 15:35 certd
-rw-------  1 root root 1006 Dec  6 13:22 config.toml
-rw-------  1 root root  19K Dec  1  2020 config.toml.edge.template
-rw-------  1 root root 9.7K Sep 16  2020 config.toml.template
drwxr-xr-x  3 root root 4.0K Nov  2 15:35 edged
drwxr-xr-x  3 root root 4.0K Nov  2 15:35 identityd
drwxr-xr-x  3 root root 4.0K Nov  2 15:35 keyd
drwx------  4 pi   root 4.0K Dec 12 11:14 storage
drwxr-xr-x  3 root root 4.0K Nov  2 15:35 tpmd
pi@edge-dev-pi:~ $ ls -lha /etc/aziot/storage/
total 32K
drwx------ 4 pi   root 4.0K Dec 12 11:14 .
drwxr-xr-x 8 root root 4.0K Dec  6 13:22 ..
drwx------ 3 pi   root  12K Jan 18 15:22 edgeAgent
drwx------ 2 pi   root  12K Jan 19 00:53 edgeHub

support_bundle_2023_01_16_13_46_18_UTC.zip

FinitelyFailed commented 1 year ago

@lfitchett, I would love to get some input on this issue.

lfitchett commented 1 year ago

@FinitelyFailed Sorry for the late response. Can you please try removing the EDGEHUBUSER_ID=1000 from your edgehub create options?

FinitelyFailed commented 1 year ago

@lfitchett I'll try that if I find a device where this has happened to the edgeHub. However this often also happen to edgeAgent. Should the same approach be use there as well?

As far as I understand the EDGEHUBUSER_ID and EDGEAGENTUSER_ID is used to set the correct owner of the storage dictionaries on the host? And that it is very much needed to be able to persist data from the system modules on the host. Is that correct? Can you please explain a bit more in detail?

lfitchett commented 1 year ago

The issue you are seeing is edgehub being unable to access a file inside the container's storage. It's trying to access a root folder (/home/edgehubuser/.dotnet/corefx/cryptography/x509stores/root), but because it is set to user 1000 it is unable to do so.

FinitelyFailed commented 1 year ago

Ok, I'll try that, thanks! But as I said, this error appears for edgeAgent as well, seemingly at random. Should I remove EDGEAGENTUSER_ID from its create options as well?

lfitchett commented 1 year ago

Yes, please do

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.

anormalpersonBE commented 1 year ago

@FinitelyFailed Did the last comment fix your issue? or how did you go about this?