Iotedge: IoT edge runtime with DPS and X.509 always reconfigures modules on start

[florianbader]

Expected Behavior

The runtime only reconfigures modules on start if the DPS sub status is DeviceDataMigrated or DeviceDataReset.

Current Behavior

The runtime always reconfigures modules because even for already assigned devices the DPS sub status is always InitialAssignment.

Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

1. Use the iotedge script to generate certificates for root, an intermediate and a device
2. Add the root CA to DPS and verify
3. Add group enrollment for root CA with static configuration for a single IoT Hub and set handling of re-provisiong to never re-provision
4. Configure device certificates on device and restart (use AMQP)
5. Deploy dummy module
6. Restart iotedge
7. Check logs

Context (Environment)

Output of iotedge check

iotedge check

Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ config.yaml has correct hostname - OK
√ config.yaml has correct URIs for daemon mgmt endpoint - OK
√ latest security daemon - OK
√ host time is close to real time - OK
√ container time is close to host time - OK
√ DNS server - OK
√ production readiness: identity certificates expiry - OK
√ production readiness: certificates - OK
√ production readiness: container engine - OK
√ production readiness: logs policy - OK
‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning

Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with DPS endpoint - OK
√ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
√ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
√ container on the default network can connect to IoT Hub AMQP port - OK
√ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the default network can connect to IoT Hub MQTT port - OK
√ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK
√ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK

23 check(s) succeeded.
2 check(s) raised warnings. Re-run with --verbose for more details.

Device Information

• Host OS [e.g. Ubuntu 16.04, Ubuntu 18.04, Windows IoT Core]: Raspbian Stretch
• Architecture [e.g. amd64, arm32, arm64]: arm32
• Container OS [e.g. Linux containers, Windows containers]: Linux containers

Runtime Versions

• iotedged [run iotedge version]: 1.0.9.4
• Edge Agent [image tag (e.g. 1.0.0)]: 1.0
• Edge Hub [image tag (e.g. 1.0.0)]: 1.0
• Docker/Moby [run docker version]: 3.0.12+azure

Logs

iotedged logs

Jul 24 10:25:26 device1 systemd[1]: Started Azure IoT Edge daemon.
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Starting Azure IoT Edge Security Daemon
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Version - 1.0.9.4
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Using config file: /etc/iotedge/config.yaml
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Configuring certificates...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Configuring the Device CA certificate using "/home/iotedge/certs/device-ca.cert.pem".
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Configuring the Device private key using "/home/iotedge/certs/device-ca.key.pem".
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Configuring the trusted CA certificates using "/home/iotedge/certs/root.cert.pem".
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Finished configuring provisioning environment variables and certificates.
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Initializing hsm...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Finished initializing hsm.
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Initializing hsm X509 interface...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Finished initializing hsm X509 interface...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Provisioning edge device...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Starting provisioning edge device via X509 provisioning...
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [INFO] - Starting DPS registration with scope_id "xxx", registration_id "dev1"
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [DBUG] - [edgelet_http::client] Empty token source for request PUT xxx/registrations/dev1/register
Jul 24 10:25:27 device1 iotedged[11901]: 2020-07-24T08:25:27Z [DBUG] - [edgelet_http::client] Empty token source for request GET xxx/registrations/dev1/operations/4.2ccd682af5298751.2995178a-0088-4db4-ad05-a8b22b643073
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [DBUG] - [edgelet_http::client] Empty token source for request GET xxx/registrations/dev1/operations/4.2ccd682af5298751.2995178a-0088-4db4-ad05-a8b22b643073
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - DPS registration assigned device "dev1" in hub "xxx.azure-devices.net"
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Successful DPS provisioning.
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Finished provisioning edge device.
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Initializing the module runtime...
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Initializing module runtime...
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Using runtime network id azure-iot-edge
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Successfully initialized module runtime
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Finished initializing the module runtime.
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules.
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Jul 24 10:25:37 device1 iotedged[11901]: 2020-07-24T08:25:37Z [INFO] - Removing module module1...

edge-agent logs

2020-07-24 08:26:04 +00:00 Starting Edge Agent
2020-07-24 08:26:05.464 +00:00 Edge Agent Main()
<6> 2020-07-24 08:26:06.882 +00:00 [INF] - Initializing Edge Agent.
<6> 2020-07-24 08:26:08.154 +00:00 [INF] - Version - 1.0.9.4.32971639 (12d55e582cc7ce95c8abfe11eddfbbc938ed6001)
<6> 2020-07-24 08:26:08.603 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"EnableUploadLogs":false,"EnableGetLogs":false,"EnableMetrics":false}
<6> 2020-07-24 08:26:09.531 +00:00 [INF] - Installing certificates [CN=xxx, O=xxx, C=DE:05/30/2030 08:37:39] to Root
<6> 2020-07-24 08:26:12.379 +00:00 [INF] - Created persistent store at /tmp/edgeAgent
<6> 2020-07-24 08:26:12.922 +00:00 [INF] - Started operation refresh twin config
<6> 2020-07-24 08:26:13.093 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...
<6> 2020-07-24 08:26:13.362 +00:00 [INF] - Registering request handler RestartModule
<6> 2020-07-24 08:26:18.324 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only.
<6> 2020-07-24 08:26:19.079 +00:00 [INF] - Initialized new module client with subscriptions enabled
<4> 2020-07-24 08:26:19.253 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup file (backup.json) instead
<6> 2020-07-24 08:26:19.293 +00:00 [INF] - Edge agent config backup file does not exist - backup.json
<6> 2020-07-24 08:26:19.573 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 17 and reported properties version 84.
<6> 2020-07-24 08:26:26.703 +00:00 [INF] - Plan execution started for deployment 17
<6> 2020-07-24 08:26:34.627 +00:00 [INF] - Executing command: "Command Group: (\n  [Create module module1]\n  [Start module module1]\n)"
<6> 2020-07-24 08:26:34.628 +00:00 [INF] - Executing command: "Create module module1"
<6> 2020-07-24 08:26:36.960 +00:00 [INF] - Executing command: "Start module module1"
<6> 2020-07-24 08:26:38.964 +00:00 [INF] - Executing command: "Command Group: (\n  [Create module edgeHub]\n  [Start module edgeHub]\n)"
<6> 2020-07-24 08:26:38.964 +00:00 [INF] - Executing command: "Create module edgeHub"
<6> 2020-07-24 08:26:39.836 +00:00 [INF] - Executing command: "Start module edgeHub"
<6> 2020-07-24 08:26:42.436 +00:00 [INF] - Plan execution ended for deployment 17

Additional Information

I created a group enrollment for my root CA. The enrollment assignment is static configuration for a single selected IoT Hub. I tried setting the "handle on re-provisioning" to "re-provision and migrate data" and also "never re-provision" both with the same result. The allocation policy of DPS is "static configuration".

According to the DPS API there are only three enum values for substatus (deviceDataMigrated, deviceDataReset and initialAssignment). If I take a look at the edgelet source code those three status are the only ones mapped for x509 provisioning.

If I use the same device certificate with this sample I also only get the InitialAssignment status from DPS even if the IoT Hub didn't change and the device is already registered to the IoT Hub. If I take a look at the SDK source code there are also only those three enum values.

Because of this the code here will always trigger a reconfiguration because the status is never DeviceDataNotUpdated. If I understood the reasoning behind this correct a status of InitialAssignment shouldn't reconfigure the modules because there was no IoT Hub configured before. If the InitialAssignment should always trigger a reconfiguration to refresh the module keys why would I need to remove/add and redownload all modules again? I would even accept the remove/add if it didn't need to redownload all modules because that defeats the whole offline mode (no internet connection available on the device).

I know this might be an issue of DPS but this is a blocker for production use cases because of the offline scenario of edge devices.

[and-rewsmith]

Someone else actually brought this to my attention this week. It is the same issue listed on stackoverflow:
https://stackoverflow.com/questions/63039789/when-using-dps-why-does-iot-edge-recreate-containers-at-reboot

I believe there is already a feature request for this. If there is not, feel free to add one:
https://feedback.azure.com/forums/907045-azure-iot-edge

[florianbader]

Funny how this issue raised simultaneously. So, is this an issue with DPS or are you open for pull requests?

I found the feature request on User Voice and send it to my customers so they can vote for it.

[and-rewsmith]

We are open for PRs, but I would make sure that people are on the same page with your specific changes so no time is wasted. Feel free to reopen the issue and describe your intended change here.

[chipalost]

Let's keep this issue open until it's resolved. It's been reported in a couple forums and the current behavior is definitely problematic.

Internal investigation is pointing to an issue with a value returned from DPS. We can link our internal bug to the bug we're filing on DPS. Once the issue gets resolved we can close this GitHub issue.

[github-actions[bot]]

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

[ksaye]

@veyalla Is there anything you need form @florianbader or I on this? I now have another issue very related to this.

[veyalla]

@ksaye Don't need anything at this point, thanks. We have concluded that this is not a regression, this has always been the behavior. We're still investigating if it can be improved.

[chipalost]

@florianbader, you may have noticed that 1.0.10 was released a couple days ago. It does not have the fix to this issue but it should be available soon in a servicing release to 1.0.10. We released 1.0.10 without the fix as it contains some security fixes that couldn't wait on us completing the fix for the issue discussed in this thread.

[fgheysels]

Not sure if I understand this issue completely. Does this have to do with the fact that when you restart the iotedge service for a configured device, iotedge will query IoT Hub to get information about it's deployment and then apply that configuration instead of first starting with it's last known deployment ?
We're currently seeing this behavior with IoT Edge installed on vessels that are not always online. When a machine reboots and the vessel is on a sattelite link, IoT Edge just doesn't apply its last know deployment and so the modules are not loaded until we're back on a better connection.

[chipalost]

@arsing @eustacea, please help fgheysels determine whether the issue he is seeing is related to this bug or is a completely different issue.

[Vijay-Karthick]

Not sure if I understand this issue completely. Does this have to do with the fact that when you restart the iotedge service for a configured device, iotedge will query IoT Hub to get information about it's deployment and then apply that configuration instead of first starting with it's last known deployment ?
We're currently seeing this behavior with IoT Edge installed on vessels that are not always online. When a machine reboots and the vessel is on a sattelite link, IoT Edge just doesn't apply its last know deployment and so the modules are not loaded until we're back on a better connection.

Hi @fgheysels
The problem I face is for IoT devices using TPM and DPS. Everytime a device reboots, all IoT Edge module containers are recreated, leading to data loss. This is not the case when I have a static SAS connection string in the config.yaml file. @ksaye created a feedback ticket a while ago:
https://feedback.azure.com/forums/907045-azure-iot-edge/suggestions/40983106-do-not-delete-modules-at-restart-when-using-dps

[fgheysels]

When a device reboots, isn't it normal that the containers are recreated ? Or do you mean : repulled from the remote container registry ?
What I face, is the fact that on reboot, the 'deployment' manifest is retrieved again from IoT Hub, and if IoT Hub is at that moment not reachable, my containers are not being started.
I think it would make more sense if, on reboot of iotedge, the last known deployment manifest is applied and the containers are pulled from the local container registry. Afterwards, IoT Edge can check if there's a new deployment available in iothub.

[drididh]

Hello,
is there any news about this bug? I have the same problem in auto provisioning with symmetric key. The version of my iotedge is 1.0.9. Below my logs :

Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules.
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Removing module edgeHub...
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Removing module edgeAgent...
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Successfully removed module edgeAgent
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Successfully removed module edgeHub
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Finished provisioning edge device.
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Starting management API...
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Starting workload API...
Dec 04 20:42:26 GatewayVM1 iotedged[18409]: 2020-12-04T19:42:26Z [INFO] - Starting watchdog with 60 second frequency...

[Vijay-Karthick]

When a device reboots, isn't it normal that the containers are recreated ? Or do you mean : repulled from the remote container registry ?
What I face, is the fact that on reboot, the 'deployment' manifest is retrieved again from IoT Hub, and if IoT Hub is at that moment not reachable, my containers are not being started.
I think it would make more sense if, on reboot of iotedge, the last known deployment manifest is applied and the containers are pulled from the local container registry. Afterwards, IoT Edge can check if there's a new deployment available in iothub.

@fgheysels : Is this still an issue you face? I have a use case where the device will go offline for extended periods of time. I'll have to check if I face the same behavior.

[fgheysels]

Yes, we're still facing this issue and actually, it is quite problematic in our case.
We have vessels sailing around the ocean. Those vessels sometimes have a limited or metered connection and if that's the case, we're unable to download containers. So, it would be really nice if, upon reboot, iotedge redeploys its last known configuration and uses the containers that it has pulled and that are available locally, before attempting to check / download a new deployment.

[eustacea]

We believe all fixes are in. @veyalla could you evaluate for possible closure?

[veyalla]

That is correct, the fix is in 1.0.10.2 version of iotedged via https://github.com/Azure/iotedge/commit/23215094cdd11fd5170d42798ebac509b132a8fd.

Note: you also need a new DPS enrollment for this to work since the fix involved changes to the DPS service as well to return a new substatus.

FYI - @ksaye, @florianbader - thanks for your patience while we took care of this one. Please test and let us know if you run into any issues.

[florianbader]

@veyalla @eustacea I'm still having problems with this.
I updated everything to 10.0.10.2-1, changed my configuration to dynamic_reprovisioning: true and always_reprovision_on_startup: false and deleted all cached certificates (/var/lib/iotedge/hsm/{certs,cert_keys}).

After restarting I'm getting the new Device registration is unchanged in Azure and matches local provisioning backup. message and my modules are started instead of reconfigured which is great.

But if I restart the runtime I get a Obtaining workload CA failed. Triggering reconfiguration message which stops, removes and downloads the modules again. On the successful first run I get Obtaining workload CA succeeded..

Changing dynamic_reprovisioning to false gives me the same result.

iotedged logs

Dec 08 10:08:05 device-server iotedged[16378]: 2020-12-08T09:08:05Z [INFO] - [work] - - - [2020-12-08 09:08:05.951249749 UTC] "POST /modules/%24edgeHub/genid/637308306805488864/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 2792 "-" "-" auth_id(-)
Dec 08 10:08:12 device-server iotedged[16378]: 2020-12-08T09:08:12Z [INFO] - Successfully stopped module module3
Dec 08 10:08:12 device-server iotedged[16378]: 2020-12-08T09:08:12Z [INFO] - [mgmt] - - - [2020-12-08 09:08:12.966930458 UTC] "POST /modules/module3/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 08 10:08:12 device-server iotedged[16378]: 2020-12-08T09:08:12Z [INFO] - Successfully stopped module module1
Dec 08 10:08:12 device-server iotedged[16378]: 2020-12-08T09:08:12Z [INFO] - [mgmt] - - - [2020-12-08 09:08:12.993834217 UTC] "POST /modules/module1/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 08 10:08:13 device-server iotedged[16378]: 2020-12-08T09:08:13Z [INFO] - Successfully stopped module module2
Dec 08 10:08:13 device-server iotedged[16378]: 2020-12-08T09:08:13Z [INFO] - [mgmt] - - - [2020-12-08 09:08:13.041184828 UTC] "POST /modules/module2/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 08 10:08:14 device-server iotedged[16378]: 2020-12-08T09:08:14Z [INFO] - Successfully stopped module edgeHub
Dec 08 10:08:14 device-server iotedged[16378]: 2020-12-08T09:08:14Z [INFO] - [mgmt] - - - [2020-12-08 09:08:14.824821921 UTC] "POST /modules/edgeHub/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:08:16Z [INFO] - Successfully stopped module edgeAgent
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:08:16Z [INFO] - Edge runtime will stop because of the shutdown signal.
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:08:16Z [INFO] - Shutdown complete.
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:05:24Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:05:35Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:05:35Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:06:00Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:06:00Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:06:29Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:remove_if_cert_and_key_exist_by_alias:1443) Certificate and key file for alias do not exist $edgeHub637308306805488864server
Dec 08 10:08:16 device-server iotedged[16378]: 2020-12-08T09:06:29Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: $edgeHub637308306805488864server

The errors above might be unrelated, because I'm getting the same problem even when those errors don't appear.

Dec 08 10:08:16 device-server systemd[1]: Stopped Azure IoT Edge daemon.
Dec 08 10:08:16 device-server systemd[1]: Started Azure IoT Edge daemon.
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Starting Azure IoT Edge Security Daemon
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Version - 1.0.10.2
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Using config file: /etc/iotedge/config.yaml
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Configuring certificates...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Configuring the Device CA certificate using "/home/iotedge/certs/device-ca.cert.pem".
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Configuring the Device private key using "/home/iotedge/certs/device-ca.key.pem".
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Configuring the trusted CA certificates using "/home/iotedge/certs/root.cert.pem".
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Finished configuring provisioning environment variables and certificates.
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Initializing hsm...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Finished initializing hsm.
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Initializing hsm X509 interface...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Finished initializing hsm X509 interface...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Provisioning edge device...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Starting provisioning edge device via X509 provisioning...
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [INFO] - Starting DPS registration with scope_id "xxxxx", registration_id "device"
Dec 08 10:08:16 device-server iotedged[18843]: 2020-12-08T09:08:16Z [DBUG] - [edgelet_http::client] Empty token source for request PUT xxxxx/registrations/device/register
Dec 08 10:08:17 device-server iotedged[18843]: 2020-12-08T09:08:17Z [DBUG] - [edgelet_http::client] Empty token source for request GET xxxxx/registrations/device/operations/4.2ccd682af5298751.9fcd89be-ff8b-4c0b-98c4-6b9dd0c0c7f0
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [DBUG] - [edgelet_http::client] Empty token source for request GET xxxxx/registrations/device/operations/4.2ccd682af5298751.9fcd89be-ff8b-4c0b-98c4-6b9dd0c0c7f0
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - DPS registration assigned device "device" in hub "xxxxx.azure-devices.net"
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Restoring device credentials from backup
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Device registration is unchanged in Azure and matches local provisioning backup.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successful DPS provisioning.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Finished provisioning edge device.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Initializing the module runtime...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Initializing module runtime...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Using runtime network id azure-iot-edge
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully initialized module runtime
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Finished initializing the module runtime.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping all modules...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module module1...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module edgeHub...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module module4...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module module2...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module module3...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Stopping module edgeAgent...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module module1
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module module2
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module module3
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module module4
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module edgeHub
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] - Could not stop module edgeAgent
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [WARN] -         caused by: Target of operation already in this state
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Finished stopping modules.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Detecting if configuration file has changed...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - No change to configuration file detected.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Edge issuer CA expiration date: 2030-05-30T09:00:42Z
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Obtaining workload CA failed. Triggering reconfiguration
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing all modules...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module module1...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module edgeHub...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module module4...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module module2...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module module3...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Removing module edgeAgent...
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module edgeHub
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module module1
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module module4
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module module2
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module edgeAgent
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Successfully removed module module3
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Finished removing modules.
Dec 08 10:08:27 device-server iotedged[18843]: 2020-12-08T09:08:27Z [INFO] - Edge issuer CA expiration date: 2030-05-30T09:00:42Z
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Starting management API...
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Starting workload API...
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Starting watchdog with 60 second frequency...
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API.
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API.
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Checking edge runtime status
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Creating and starting edge runtime module edgeAgent
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [DBUG] - [edgelet_http::client] Success generating token for request GET /devices/device/modules/$edgeAgent
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Updating identity for module $edgeAgent
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/$edgeAgent
Dec 08 10:08:52 device-server iotedged[18843]: 2020-12-08T09:08:52Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0...
Dec 08 10:08:53 device-server iotedged[18843]: 2020-12-08T09:08:53Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0
Dec 08 10:08:53 device-server iotedged[18843]: 2020-12-08T09:08:53Z [INFO] - Creating module edgeAgent...
Dec 08 10:08:53 device-server iotedged[18843]: 2020-12-08T09:08:53Z [DBUG] - [edgelet_docker::runtime] Creating container edgeAgent with image mcr.microsoft.com/azureiotedge-agent:1.0
Dec 08 10:08:55 device-server iotedged[18843]: 2020-12-08T09:08:55Z [INFO] - Successfully created module edgeAgent
Dec 08 10:08:55 device-server iotedged[18843]: 2020-12-08T09:08:55Z [INFO] - Starting module edgeAgent...
Dec 08 10:08:57 device-server iotedged[18843]: 2020-12-08T09:08:57Z [INFO] - Successfully started module edgeAgent
Dec 08 10:09:00 device-server iotedged[18843]: 2020-12-08T09:09:00Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:00 device-server iotedged[18843]: 2020-12-08T09:09:00Z [INFO] - [work] - - - [2020-12-08 09:09:00.716784650 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 2168 "-" "-" auth_id(-)
Dec 08 10:09:02 device-server iotedged[18843]: 2020-12-08T09:09:02Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:02 device-server iotedged[18843]: 2020-12-08T09:09:02Z [DBUG] - [edgelet_http_mgmt::server::system_info::get] Get System Information
Dec 08 10:09:02 device-server iotedged[18843]: 2020-12-08T09:09:02Z [INFO] - Querying system info...
Dec 08 10:09:02 device-server iotedged[18843]: none
Dec 08 10:09:02 device-server iotedged[18843]: 2020-12-08T09:09:02Z [INFO] - Successfully queried system info
Dec 08 10:09:02 device-server iotedged[18843]: 2020-12-08T09:09:02Z [INFO] - [mgmt] - - - [2020-12-08 09:09:02.800453131 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 310 "-" "-" auth_id(-)
Dec 08 10:09:05 device-server iotedged[18843]: 2020-12-08T09:09:05Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:05 device-server iotedged[18843]: 2020-12-08T09:09:05Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:05 device-server iotedged[18843]: 2020-12-08T09:09:05Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:05 device-server iotedged[18843]: 2020-12-08T09:09:05Z [INFO] - [work] - - - [2020-12-08 09:09:05.713315104 UTC] "POST /modules/%24edgeAgent/genid/637308306805488864/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_http_mgmt::server::system_info::get] Get System Information
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [INFO] - Querying system info...
Dec 08 10:09:06 device-server iotedged[18843]: none
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [INFO] - Successfully queried system info
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [INFO] - [mgmt] - - - [2020-12-08 09:09:06.378219881 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 310 "-" "-" auth_id(-)
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_http_mgmt::server::module::list] List modules
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:06 device-server iotedged[18843]: 2020-12-08T09:09:06Z [INFO] - [mgmt] - - - [2020-12-08 09:09:06.827239181 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [INFO] - [work] - - - [2020-12-08 09:09:08.251172878 UTC] "POST /modules/%24edgeAgent/genid/637308306805488864/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6145 "-" "-" auth_id(-)
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:08 device-server iotedged[18843]: 2020-12-08T09:09:08Z [DBUG] - [edgelet_http::client] Success generating token for request GET /devices/device/modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [INFO] - [mgmt] - - - [2020-12-08 09:09:10.076561620 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 610 "-" "-" auth_id(-)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/module3
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/$edgeHub
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/module4
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/module2
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [DBUG] - [edgelet_http::client] Success generating token for request PUT /devices/device/modules/module1
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [INFO] - [mgmt] - - - [2020-12-08 09:09:10.448714758 UTC] "PUT /identities/module3?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [INFO] - [mgmt] - - - [2020-12-08 09:09:10.521343155 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
Dec 08 10:09:10 device-server iotedged[18843]: 2020-12-08T09:09:10Z [INFO] - [mgmt] - - - [2020-12-08 09:09:10.584709366 UTC] "PUT /identities/module2?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
Dec 08 10:09:11 device-server iotedged[18843]: 2020-12-08T09:09:11Z [INFO] - [mgmt] - - - [2020-12-08 09:09:11.111252529 UTC] "PUT /identities/module1?api-version=2020-07-07 HTTP/1.1" 200 OK 96 "-" "-" auth_id(-)
Dec 08 10:09:11 device-server iotedged[18843]: 2020-12-08T09:09:11Z [INFO] - [mgmt] - - - [2020-12-08 09:09:11.164517240 UTC] "PUT /identities/module4?api-version=2020-07-07 HTTP/1.1" 200 OK 104 "-" "-" auth_id(-)
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10.3...
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10.3
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_http_mgmt::server::module::prepare_update] Successfully pulled new image for module edgeAgent
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [INFO] - [mgmt] - - - [2020-12-08 09:09:12.788711901 UTC] "POST /modules/edgeAgent/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [INFO] - Updating and starting module edgeAgent
Dec 08 10:09:12 device-server iotedged[18843]: 2020-12-08T09:09:12Z [INFO] - Removing module edgeAgent...
Dec 08 10:09:14 device-server iotedged[18843]: 2020-12-08T09:09:14Z [INFO] - Successfully removed module edgeAgent
Dec 08 10:09:14 device-server iotedged[18843]: 2020-12-08T09:09:14Z [DBUG] - [edgelet_http_mgmt::server::module::update] Removed existing module edgeAgent
Dec 08 10:09:14 device-server iotedged[18843]: 2020-12-08T09:09:14Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0.10.3...
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0.10.3
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [DBUG] - [edgelet_http_mgmt::server::module::update] Successfully pulled new image for module edgeAgent
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [INFO] - Creating module edgeAgent...
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [DBUG] - [edgelet_docker::runtime] Creating container edgeAgent with image mcr.microsoft.com/azureiotedge-agent:1.0.10.3
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [INFO] - Successfully created module edgeAgent
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [DBUG] - [edgelet_http_mgmt::server::module::update] Created module edgeAgent
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [INFO] - Starting module edgeAgent
Dec 08 10:09:15 device-server iotedged[18843]: 2020-12-08T09:09:15Z [INFO] - Starting module edgeAgent...
Dec 08 10:09:17 device-server iotedged[18843]: 2020-12-08T09:09:17Z [INFO] - Successfully started module edgeAgent
Dec 08 10:09:17 device-server iotedged[18843]: 2020-12-08T09:09:17Z [INFO] - [mgmt] - - - [2020-12-08 09:09:17.472740933 UTC] "PUT /modules/edgeAgent?api-version=2020-07-07&start=true HTTP/1.1" 200 OK 1674 "-" "-" auth_id(-)
Dec 08 10:09:17 device-server iotedged[18843]: 2020-12-08T09:09:17Z [ERR!] - server connection error: (unknown)
Dec 08 10:09:17 device-server iotedged[18843]: 2020-12-08T09:09:17Z [ERR!] - error writing a body to connection: Broken pipe (os error 32)
Dec 08 10:09:20 device-server iotedged[18843]: 2020-12-08T09:09:20Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:20 device-server iotedged[18843]: 2020-12-08T09:09:20Z [INFO] - [work] - - - [2020-12-08 09:09:20.419276739 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 2168 "-" "-" auth_id(-)
Dec 08 10:09:22 device-server iotedged[18843]: 2020-12-08T09:09:22Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:22 device-server iotedged[18843]: 2020-12-08T09:09:22Z [DBUG] - [edgelet_http_mgmt::server::system_info::get] Get System Information
Dec 08 10:09:22 device-server iotedged[18843]: 2020-12-08T09:09:22Z [INFO] - Querying system info...
Dec 08 10:09:22 device-server iotedged[18843]: none
Dec 08 10:09:22 device-server iotedged[18843]: 2020-12-08T09:09:22Z [INFO] - Successfully queried system info
Dec 08 10:09:22 device-server iotedged[18843]: 2020-12-08T09:09:22Z [INFO] - [mgmt] - - - [2020-12-08 09:09:22.461273290 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 310 "-" "-" auth_id(-)
Dec 08 10:09:25 device-server iotedged[18843]: 2020-12-08T09:09:25Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:25 device-server iotedged[18843]: 2020-12-08T09:09:25Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:25 device-server iotedged[18843]: 2020-12-08T09:09:25Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:25 device-server iotedged[18843]: 2020-12-08T09:09:25Z [INFO] - [work] - - - [2020-12-08 09:09:25.720829826 UTC] "POST /modules/%24edgeAgent/genid/637308306805488864/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [DBUG] - [edgelet_http_mgmt::server::system_info::get] Get System Information
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [INFO] - Querying system info...
Dec 08 10:09:26 device-server iotedged[18843]: none
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [INFO] - Successfully queried system info
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [INFO] - [mgmt] - - - [2020-12-08 09:09:26.162368480 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 310 "-" "-" auth_id(-)
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:26 device-server iotedged[18843]: 2020-12-08T09:09:26Z [INFO] - [work] - - - [2020-12-08 09:09:26.600876335 UTC] "POST /modules/%24edgeAgent/genid/637308306805488864/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6124 "-" "-" auth_id(-)
Dec 08 10:09:27 device-server iotedged[18843]: 2020-12-08T09:09:27Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:27 device-server iotedged[18843]: 2020-12-08T09:09:27Z [DBUG] - [edgelet_http_mgmt::server::module::list] List modules
Dec 08 10:09:27 device-server iotedged[18843]: 2020-12-08T09:09:27Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:27 device-server iotedged[18843]: 2020-12-08T09:09:27Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:27 device-server iotedged[18843]: 2020-12-08T09:09:27Z [INFO] - [mgmt] - - - [2020-12-08 09:09:27.426876632 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 785 "-" "-" auth_id(-)
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [INFO] - [work] - - - [2020-12-08 09:09:29.161836496 UTC] "POST /modules/%24edgeAgent/genid/637308306805488864/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6145 "-" "-" auth_id(-)
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_http] accepted new connection (unknown)
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [DBUG] - [edgelet_http::client] Success generating token for request GET /devices/device/modules
Dec 08 10:09:29 device-server iotedged[18843]: 2020-12-08T09:09:29Z [INFO] - [mgmt] - - - [2020-12-08 09:09:29.510489846 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 610 "-" "-" auth_id(-)
Dec 08 10:09:31 device-server iotedged[18843]: 2020-12-08T09:09:31Z [INFO] - Pulling image xxx.azurecr.io/dev/module4:1.1.14...
Dec 08 10:09:34 device-server iotedged[18843]: 2020-12-08T09:09:34Z [INFO] - Successfully pulled image xxx.azurecr.io/dev/module4:1.1.14
Dec 08 10:09:34 device-server iotedged[18843]: 2020-12-08T09:09:34Z [DBUG] - [edgelet_http_mgmt::server::module::create] Successfully pulled new image for module module4
Dec 08 10:09:34 device-server iotedged[18843]: 2020-12-08T09:09:34Z [INFO] - Creating module module4...
Dec 08 10:09:34 device-server iotedged[18843]: 2020-12-08T09:09:34Z [DBUG] - [edgelet_docker::runtime] Creating container module4 with image xxx.azurecr.io/dev/module4:1.1.14
Dec 08 10:09:34 device-server iotedged[18843]: 2020-12-08T09:09:34Z [INFO] - Successfully created module module4

edgeAgent logs

<6> 2020-12-08 09:09:20.140 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2020-12-08 09:09:20.718 +00:00 [INF] - Installing certificates [CN=xxx, O=xxx, C=DE:05/30/2030 08:37:39] to Root
<6> 2020-12-08 09:09:21.421 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics
<6> 2020-12-08 09:09:22.292 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2020-12-08 09:09:22.317 +00:00 [INF] - Started operation Get system resources
<6> 2020-12-08 09:09:22.326 +00:00 [INF] - Collecting metadata metrics
<6> 2020-12-08 09:09:22.676 +00:00 [INF] - Set metadata metrics: 1.0.10.3.36904102 (95aa3cb67f16386be6c76e83feeb6538f6e040b9), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"armv7l","Version":"1.0.10.2","Provisioning":{"Type":"dps.x509","DynamicReprovisioning":true},"ServerVersion":"3.0.13+azure","KernelVersion":"4.19.95-rt38-v7+","OperatingSystem":"Raspbian GNU/Linux 9 (stretch)","NumCpus":4,"Virtualized":"no"}, True
<6> 2020-12-08 09:09:22.769 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2020-12-08 09:09:22.784 +00:00 [INF] - Started operation refresh twin config
<6> 2020-12-08 09:09:22.863 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<6> 2020-12-08 09:09:24.491 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeAgent
<6> 2020-12-08 09:09:24.917 +00:00 [INF] - Started operation Metrics Scrape
<6> 2020-12-08 09:09:24.917 +00:00 [INF] - Started operation Metrics Upload
Scraping frequency: 01:00:00
Upload Frequency: 1.00:00:00
<6> 2020-12-08 09:09:26.285 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2020-12-08 09:09:26.286 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2020-12-08 09:09:26.288 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2020-12-08 09:09:26.288 +00:00 [INF] - Registering request handler RestartModule
<6> 2020-12-08 09:09:26.880 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only.
<6> 2020-12-08 09:09:27.368 +00:00 [INF] - Initialized new module client with subscriptions enabled
<6> 2020-12-08 09:09:28.726 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 405 and reported properties version 620.
<6> 2020-12-08 09:09:31.198 +00:00 [INF] - Plan execution started for deployment 405
<6> 2020-12-08 09:09:31.299 +00:00 [INF] - Executing command: "Command Group: (\n  [Create module module4]\n  [Start module module4]\n)"
<6> 2020-12-08 09:09:31.323 +00:00 [INF] - Executing command: "Create module module4"
<6> 2020-12-08 09:09:34.926 +00:00 [INF] - Executing command: "Start module module4"

iotedge check

Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ config.yaml has correct hostname - OK
√ config.yaml has correct URIs for daemon mgmt endpoint - OK
√ latest security daemon - OK
√ host time is close to real time - OK
√ 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: identity certificates expiry - OK
√ production readiness: certificates - OK
√ production readiness: container engine - OK
‼ production readiness: logs policy - Warning
    Container engine is not configured to rotate module logs which may cause it run out of disk space.
    Please see https://aka.ms/iotedge-prod-checklist-logs for best practices.
    You can ignore this warning if you are setting log policy per module in the Edge deployment.
√ 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

Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with DPS endpoint - OK
√ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
√ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
√ container on the default network can connect to IoT Hub AMQP port - OK
√ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the default network can connect to IoT Hub MQTT port - OK
√ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK
√ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK

23 check(s) succeeded.

[arsing]

and deleted all cached certificates (/var/lib/iotedge/hsm/{certs,cert_keys}).

That includes the workload CA, so one forced reconfiguration after that is to be expected.

After restarting I'm getting the new Device registration is unchanged in Azure and matches local provisioning backup. message and my modules are started instead of reconfigured which is great.

Later you say "if I restart the runtime", so what did you restart here? The iotedged service? Or the whole device?

On the successful first run I get Obtaining workload CA succeeded..

Do you mean the previous run from paragraph 2? Or the first successful run after the events of paragraph 3?

The errors above might be unrelated, because I'm getting the same problem even when those errors don't appear.

The errors probably still appear. Are you filtering the journalctl output with -u iotedge ? If so, remove that.

[florianbader]

Sorry for the confusion, here's what I'm doing:

sudo systemctl stop iotedge
sudo rm /var/lib/iotedge/hsm/certs/*
sudo rm /var/lib/iotedge/hsm/cert_keys/*
sudo systemctl start iotedge

Here's the fun part, this gives me the following:

Device registration is unchanged in Azure and matches local provisioning backup.
...
Obtaining workload CA succeeded.

The modules are stopped and started but not downloaded again.
After that I'm restarting the iotedged service:

sudo systemctl restart iotedge

This gives me the following (journalctl without -u) output. Modules are stopped, removed and downloaded again.

iotedged logs (after first restart)

Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:54:24Z [INFO] - Shutdown complete.
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:15Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:26Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:26Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:34Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:34Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:56Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:remove_if_cert_and_key_exist_by_alias:1443) Certificate and key file for alias do not exist $edgeHub637308306805488864server
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:56Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: $edgeHub637308306805488864server
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:56Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHub637308306805488864server
Dec 08 22:54:24 device1-server iotedged[3494]: 2020-12-08T21:51:56Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
Dec 08 22:54:24 device1-server systemd[1]: Stopped Azure IoT Edge daemon.
...
Device registration is unchanged in Azure and matches local provisioning backup.
...
Obtaining workload CA failed. Triggering reconfiguration

If I restart the iotedged service again I'm getting the same:

iotedged logs (after second restart)

Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:59:45Z [INFO] - Shutdown complete.
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:24Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1773) Could not verify certificate /var/lib/iotedge/hsm/certs/iotedged-workload-caGrw6jn-HzmxG8plggnAjPDuGJr0qGW94X1KnqPwU9ng_.cert.pem using issuer certificate /home/iotedge/Certificates/device-ca.cert.pem.
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1775) Verification status: 0, Error: 2, Msg: 'unable to get issuer certificate'
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:load_if_cert_and_key_exist_by_alias:1521) Certificate for alias is invalid iotedged-workload-ca
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2701) Failed certificate validation for alias iotedged-workload-ca
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_create_certificate:288) Could not create certificate in the store
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:36Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: iotedged-workload-ca
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:36Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:36Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1773) Could not verify certificate /var/lib/iotedge/hsm/certs/iotedge-tlsTLNi220opyZbShBY7-R4NIxntUhft8tKSA59Ln8BbSA_.cert.pem using issuer certificate /home/iotedge/Certificates/device-ca.cert.pem.
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1775) Verification status: 0, Error: 2, Msg: 'unable to get issuer certificate'
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:load_if_cert_and_key_exist_by_alias:1521) Certificate for alias is invalid iotedge-tls
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2701) Failed certificate validation for alias iotedge-tls
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_create_certificate:288) Could not create certificate in the store
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: iotedge-tls
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:04Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:51Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: $edgeHub637308306805488864server
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:51Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHub637308306805488864server
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:55:51Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
Dec 08 22:59:45 device1-server systemd[1]: Stopped Azure IoT Edge daemon.
...
Device registration is unchanged in Azure and matches local provisioning backup.
...
Obtaining workload CA failed. Triggering reconfiguration

The iotedged logs from my post above are after restarting the iotedged service when obtaining the workload CA failed and the modules get downloaded again.

[arsing]

Actually I misspoke earlier.

That includes the workload CA, so one forced reconfiguration after that is to be expected.

This isn't true. The workload CA will be regenerated without needing a reconfiguration, so even a single reconfiguration won't happen.

---

Secondly, I don't understand why you're deleting the certs in the first place. What are you trying to do?

---

Your problem seems to arise from the newly generated workload CA failing to validate against your custom device CA.

Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1773) Could not verify certificate /var/lib/iotedge/hsm/certs/iotedged-workload-caGrw6jn-HzmxG8plggnAjPDuGJr0qGW94X1KnqPwU9ng_.cert.pem using issuer certificate /home/iotedge/Certificates/device-ca.cert.pem.
Dec 08 22:59:45 device1-server iotedged[6042]: 2020-12-08T21:54:35Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:check_certificates:1775) Verification status: 0, Error: 2, Msg: 'unable to get issuer certificate'

"unable to get issuer certificate" is strange because the workload CA file should contain its issuer, ie the device CA, appended to it already. Please verify that that is the case on your device, ie that the workload CA file contains one CERTIFICATE block and then a copy of your device CA's CERTIFICATE block after that.

Also, I doubt that this is related to provisioning at all, let alone this particular feature request. Are you sure you always see this issue with always_reprovision_on_startup: false and never with always_reprovision_with_startup: true , with the same version of iotedged both times?

---

Anyway, I do not see the thing you describe. Starting from a clean slate, with config.yaml containing:

provisioning:
  source: 'dps'
  global_endpoint: 'https://global.azure-devices-provisioning.net'
  scope_id: '<>'
  attestation:
    method: 'symmetric_key'
    registration_id: '<>'
    symmetric_key: '<>'
  always_reprovision_on_startup: false
  dynamic_reprovisioning: true

certificates:
  device_ca_cert: '/iotedge/device-ca.pem'
  device_ca_pk: '/iotedge/device-ca.key.pem'
  trusted_ca_certs: '/iotedge/trust-bundle.pem'

...

I start iotedged for the first time:

Click here

<6>2021-01-06T22:54:15Z [INFO] - Starting Azure IoT Edge Security Daemon
<6>2021-01-06T22:54:15Z [INFO] - Version - 1.0.10.4
<6>2021-01-06T22:54:15Z [INFO] - Using config file: /iotedge/config.yaml
<6>2021-01-06T22:54:15Z [INFO] - Configuring /iotedge as the home directory.
<6>2021-01-06T22:54:15Z [INFO] - Configuring certificates...
<6>2021-01-06T22:54:15Z [INFO] - Configuring the Device CA certificate using "/iotedge/device-ca.pem".
<6>2021-01-06T22:54:15Z [INFO] - Configuring the Device private key using "/iotedge/device-ca.key.pem".
<6>2021-01-06T22:54:15Z [INFO] - Configuring the trusted CA certificates using "/iotedge/trust-bundle.pem".
<6>2021-01-06T22:54:15Z [INFO] - Finished configuring provisioning environment variables and certificates.
<6>2021-01-06T22:54:15Z [INFO] - Initializing hsm...
<6>2021-01-06T22:54:15Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
<3>2021-01-06T22:54:15Z [ERR!] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_utils.c:read_file_into_buffer_impl:167) Could not open file for reading /iotedge/hsm/enc_keys/edgelet-masterWt5mT2xpO72EPKlt2Tt0Sq4uJCrMvfl2rzzKRB3pnyo_.enc.key.
 Errno 2 'No such file or directory'
<6>2021-01-06T22:54:15Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:load_encryption_key_from_file:817) Could not read encryption key from file.  No key file exists or is invalid or permission error.
<6>2021-01-06T22:54:15Z [INFO] - Finished initializing hsm.
<6>2021-01-06T22:54:15Z [INFO] - Provisioning edge device...
<6>2021-01-06T22:54:15Z [INFO] - Starting provisioning edge device via symmetric key...
<6>2021-01-06T22:54:15Z [INFO] - Attempting to restore provisioning backup...
<6>2021-01-06T22:54:15Z [INFO] - Provisioning backup could not be restored: Could not restore previous provisioning result
<6>2021-01-06T22:54:15Z [INFO] - Starting DPS registration with scope_id "<>", registration_id "<>"
<6>2021-01-06T22:54:25Z [INFO] - DPS registration assigned device "<>" in hub "<>.azure-devices.net"
<6>2021-01-06T22:54:25Z [INFO] - Device registration is unchanged in Azure but does not match local provisioning backup, so provisioning result substatus "reprovisionedToInitialAssignment" will be treated as "initialAssignment".
<6>2021-01-06T22:54:25Z [INFO] - Successful DPS provisioning.
<6>2021-01-06T22:54:25Z [INFO] - Finished provisioning edge device.
<6>2021-01-06T22:54:25Z [INFO] - Initializing the module runtime...
<6>2021-01-06T22:54:25Z [INFO] - Initializing module runtime...
<6>2021-01-06T22:54:25Z [INFO] - Using runtime network id azure-iot-edge
<6>2021-01-06T22:54:26Z [INFO] - Successfully initialized module runtime
<6>2021-01-06T22:54:26Z [INFO] - Finished initializing the module runtime.
<6>2021-01-06T22:54:26Z [INFO] - Stopping all modules...
<6>2021-01-06T22:54:26Z [INFO] - Finished stopping modules.
<6>2021-01-06T22:54:26Z [INFO] - Reprovisioning status InitialAssignment will trigger reconfiguration of modules.
<6>2021-01-06T22:54:26Z [INFO] - Detecting if configuration file has changed...
<6>2021-01-06T22:54:26Z [INFO] - Change to configuration file detected.
<6>2021-01-06T22:54:26Z [INFO] - Removing all modules...
<6>2021-01-06T22:54:26Z [INFO] - Finished removing modules.
<3>2021-01-06T22:54:26Z [ERR!] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:remove_if_cert_and_key_exist_by_alias:1443) Certificate and key file for alias do not exist iotedged-workload-ca
<6>2021-01-06T22:54:26Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: iotedged-workload-ca
<6>2021-01-06T22:54:26Z [INFO] - Edge issuer CA expiration date: 2022-01-06T22:48:46Z
<6>2021-01-06T22:54:26Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
<6>2021-01-06T22:54:26Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
<6>2021-01-06T22:54:26Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
<6>2021-01-06T22:54:26Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
<6>2021-01-06T22:54:26Z [INFO] - Starting management API...
<6>2021-01-06T22:54:26Z [INFO] - Starting workload API...
<6>2021-01-06T22:54:26Z [INFO] - Starting watchdog with 60 second frequency...
<6>2021-01-06T22:54:26Z [INFO] - Listening on unix:///iotedge/mgmt.sock with 1 thread for management API.
<6>2021-01-06T22:54:26Z [INFO] - Listening on unix:///iotedge/workload.sock with 1 thread for workload API.
<6>2021-01-06T22:54:26Z [INFO] - Checking edge runtime status
<6>2021-01-06T22:54:26Z [INFO] - Creating and starting edge runtime module edgeAgent
<6>2021-01-06T22:54:27Z [INFO] - Updating identity for module $edgeAgent
<6>2021-01-06T22:54:27Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.0...
<6>2021-01-06T22:54:27Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0
<6>2021-01-06T22:54:27Z [INFO] - Creating module edgeAgent...
<6>2021-01-06T22:54:27Z [INFO] - Successfully created module edgeAgent
<6>2021-01-06T22:54:27Z [INFO] - Starting module edgeAgent...
<6>2021-01-06T22:54:27Z [INFO] - Successfully started module edgeAgent

This is as expected. There was no existing provisioning backup so DPS response was treated as initial assignment. Since workload CA did not exist, it was created. Edge Agent was pulled and started.

I stopped iotedged, then ran:

$ ls -1 hsm/certs/* hsm/cert_keys/*

hsm/cert_keys/edgeHub637455692195970799serversmM2-VDX7Ak6ucbdFLPaYiYbvaitCzhlplYOAPgs4gg_.key.pem
hsm/cert_keys/iotedged-workload-caGrw6jn-HzmxG8plggnAjPDuGJr0qGW94X1KnqPwU9ng_.key.pem
hsm/cert_keys/iotedge-tlsTLNi220opyZbShBY7-R4NIxntUhft8tKSA59Ln8BbSA_.key.pem
hsm/certs/edgeHub637455692195970799serversmM2-VDX7Ak6ucbdFLPaYiYbvaitCzhlplYOAPgs4gg_.cert.pem
hsm/certs/iotedged-workload-caGrw6jn-HzmxG8plggnAjPDuGJr0qGW94X1KnqPwU9ng_.cert.pem
hsm/certs/iotedge-tlsTLNi220opyZbShBY7-R4NIxntUhft8tKSA59Ln8BbSA_.cert.pem

$ rm hsm/certs/* hsm/cert_keys/*

Then I started iotedged again:

Click here

<6>2021-01-06T22:56:31Z [INFO] - Starting Azure IoT Edge Security Daemon
<6>2021-01-06T22:56:31Z [INFO] - Version - 1.0.10.4
<6>2021-01-06T22:56:31Z [INFO] - Using config file: /iotedge/config.yaml
<6>2021-01-06T22:56:31Z [INFO] - Configuring /iotedge as the home directory.
<6>2021-01-06T22:56:31Z [INFO] - Configuring certificates...
<6>2021-01-06T22:56:31Z [INFO] - Configuring the Device CA certificate using "/iotedge/device-ca.pem".
<6>2021-01-06T22:56:31Z [INFO] - Configuring the Device private key using "/iotedge/device-ca.key.pem".
<6>2021-01-06T22:56:31Z [INFO] - Configuring the trusted CA certificates using "/iotedge/trust-bundle.pem".
<6>2021-01-06T22:56:31Z [INFO] - Finished configuring provisioning environment variables and certificates.
<6>2021-01-06T22:56:31Z [INFO] - Initializing hsm...
<6>2021-01-06T22:56:31Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
<6>2021-01-06T22:56:31Z [INFO] - Finished initializing hsm.
<6>2021-01-06T22:56:31Z [INFO] - Provisioning edge device...
<6>2021-01-06T22:56:31Z [INFO] - Starting provisioning edge device via symmetric key...
<6>2021-01-06T22:56:31Z [INFO] - Attempting to restore provisioning backup...
<6>2021-01-06T22:56:31Z [INFO] - Restoring device credentials from backup
<6>2021-01-06T22:56:31Z [INFO] - Successful DPS provisioning.
<6>2021-01-06T22:56:31Z [INFO] - Finished provisioning edge device.
<6>2021-01-06T22:56:31Z [INFO] - Initializing the module runtime...
<6>2021-01-06T22:56:31Z [INFO] - Initializing module runtime...
<6>2021-01-06T22:56:31Z [INFO] - Using runtime network id azure-iot-edge
<6>2021-01-06T22:56:31Z [INFO] - Successfully initialized module runtime
<6>2021-01-06T22:56:31Z [INFO] - Finished initializing the module runtime.
<6>2021-01-06T22:56:31Z [INFO] - Stopping all modules...
<6>2021-01-06T22:56:31Z [INFO] - Stopping module edgeHub...
<6>2021-01-06T22:56:31Z [INFO] - Stopping module tempSensor...
<6>2021-01-06T22:56:31Z [INFO] - Stopping module edgeAgent...
<4>2021-01-06T22:56:31Z [WARN] - Could not stop module edgeHub
<4>2021-01-06T22:56:31Z [WARN] -        caused by: Target of operation already in this state
<4>2021-01-06T22:56:31Z [WARN] - Could not stop module tempSensor
<4>2021-01-06T22:56:31Z [WARN] -        caused by: Target of operation already in this state
<4>2021-01-06T22:56:31Z [WARN] - Could not stop module edgeAgent
<4>2021-01-06T22:56:31Z [WARN] -        caused by: Target of operation already in this state
<6>2021-01-06T22:56:31Z [INFO] - Finished stopping modules.
<6>2021-01-06T22:56:31Z [INFO] - Detecting if configuration file has changed...
<6>2021-01-06T22:56:31Z [INFO] - No change to configuration file detected.
<6>2021-01-06T22:56:31Z [INFO] - Edge issuer CA expiration date: 2022-01-06T22:48:46Z
<6>2021-01-06T22:56:31Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
<6>2021-01-06T22:56:31Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
<6>2021-01-06T22:56:32Z [INFO] - Obtaining workload CA succeeded.
<6>2021-01-06T22:56:32Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
<6>2021-01-06T22:56:32Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
<6>2021-01-06T22:56:32Z [INFO] - Starting management API...
<6>2021-01-06T22:56:32Z [INFO] - Starting workload API...
<6>2021-01-06T22:56:32Z [INFO] - Starting watchdog with 60 second frequency...
<6>2021-01-06T22:56:32Z [INFO] - Listening on unix:///iotedge/mgmt.sock with 1 thread for management API.
<6>2021-01-06T22:56:32Z [INFO] - Listening on unix:///iotedge/workload.sock with 1 thread for workload API.
<6>2021-01-06T22:56:32Z [INFO] - Checking edge runtime status
<6>2021-01-06T22:56:32Z [INFO] - Edge runtime status is failed, starting module now...
<6>2021-01-06T22:56:32Z [INFO] - Starting module edgeAgent...
<6>2021-01-06T22:56:33Z [INFO] - Successfully started module edgeAgent

This is again as expected. Provisioning backup was restored without talking to DPS. Since workload CA did not exist, it was created. Edge Agent was not pulled again, just started.

Then I stopped and started iotedged again:

Click here

<6>2021-01-06T22:59:03Z [INFO] - Starting Azure IoT Edge Security Daemon
<6>2021-01-06T22:59:03Z [INFO] - Version - 1.0.10.4
<6>2021-01-06T22:59:03Z [INFO] - Using config file: /iotedge/config.yaml
<6>2021-01-06T22:59:03Z [INFO] - Configuring /iotedge as the home directory.
<6>2021-01-06T22:59:03Z [INFO] - Configuring certificates...
<6>2021-01-06T22:59:03Z [INFO] - Configuring the Device CA certificate using "/iotedge/device-ca.pem".
<6>2021-01-06T22:59:03Z [INFO] - Configuring the Device private key using "/iotedge/device-ca.key.pem".
<6>2021-01-06T22:59:03Z [INFO] - Configuring the trusted CA certificates using "/iotedge/trust-bundle.pem".
<6>2021-01-06T22:59:03Z [INFO] - Finished configuring provisioning environment variables and certificates.
<6>2021-01-06T22:59:03Z [INFO] - Initializing hsm...
<6>2021-01-06T22:59:03Z [INFO] (/src/iotedge/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
<6>2021-01-06T22:59:03Z [INFO] - Finished initializing hsm.
<6>2021-01-06T22:59:03Z [INFO] - Provisioning edge device...
<6>2021-01-06T22:59:03Z [INFO] - Starting provisioning edge device via symmetric key...
<6>2021-01-06T22:59:03Z [INFO] - Attempting to restore provisioning backup...
<6>2021-01-06T22:59:03Z [INFO] - Restoring device credentials from backup
<6>2021-01-06T22:59:03Z [INFO] - Successful DPS provisioning.
<6>2021-01-06T22:59:03Z [INFO] - Finished provisioning edge device.
<6>2021-01-06T22:59:03Z [INFO] - Initializing the module runtime...
<6>2021-01-06T22:59:03Z [INFO] - Initializing module runtime...
<6>2021-01-06T22:59:03Z [INFO] - Using runtime network id azure-iot-edge
<6>2021-01-06T22:59:03Z [INFO] - Successfully initialized module runtime
<6>2021-01-06T22:59:03Z [INFO] - Finished initializing the module runtime.
<6>2021-01-06T22:59:03Z [INFO] - Stopping all modules...
<6>2021-01-06T22:59:03Z [INFO] - Stopping module edgeHub...
<6>2021-01-06T22:59:03Z [INFO] - Stopping module tempSensor...
<6>2021-01-06T22:59:03Z [INFO] - Stopping module edgeAgent...
<4>2021-01-06T22:59:03Z [WARN] - Could not stop module edgeHub
<4>2021-01-06T22:59:03Z [WARN] -        caused by: Target of operation already in this state
<4>2021-01-06T22:59:03Z [WARN] - Could not stop module tempSensor
<4>2021-01-06T22:59:03Z [WARN] -        caused by: Target of operation already in this state
<4>2021-01-06T22:59:03Z [WARN] - Could not stop module edgeAgent
<4>2021-01-06T22:59:03Z [WARN] -        caused by: Target of operation already in this state
<6>2021-01-06T22:59:03Z [INFO] - Finished stopping modules.
<6>2021-01-06T22:59:03Z [INFO] - Detecting if configuration file has changed...
<6>2021-01-06T22:59:03Z [INFO] - No change to configuration file detected.
<6>2021-01-06T22:59:03Z [INFO] - Edge issuer CA expiration date: 2022-01-06T22:48:46Z
<6>2021-01-06T22:59:03Z [INFO] - Obtaining workload CA succeeded.
<6>2021-01-06T22:59:03Z [INFO] - Starting management API...
<6>2021-01-06T22:59:03Z [INFO] - Starting workload API...
<6>2021-01-06T22:59:03Z [INFO] - Starting watchdog with 60 second frequency...
<6>2021-01-06T22:59:03Z [INFO] - Listening on unix:///iotedge/mgmt.sock with 1 thread for management API.
<6>2021-01-06T22:59:03Z [INFO] - Listening on unix:///iotedge/workload.sock with 1 thread for workload API.
<6>2021-01-06T22:59:03Z [INFO] - Checking edge runtime status
<6>2021-01-06T22:59:03Z [INFO] - Edge runtime status is failed, starting module now...
<6>2021-01-06T22:59:03Z [INFO] - Starting module edgeAgent...
<6>2021-01-06T22:59:04Z [INFO] - Successfully started module edgeAgent

This is again as expected. Provisioning backup was restored without talking to DPS. Workload CA already existed so there was nothing to do. Edge Agent was not pulled again, just started.

[florianbader]

Thanks for taking a look at this.

I deleted the certs to start from a clean configuration. Nothing I would do in production, but the same problems occurs even without deleting them. The behavior is the same no matter the value of always_reprovision_on_startup.

This is my configuration:

provisioning:
  source: "dps"
  global_endpoint: "https://global.azure-devices-provisioning.net"
  scope_id: "xxx"
  attestation:
    method: "x509"
    identity_cert: "file:///home/iotedge/Certificates/device.cert.pem"
    identity_pk: "file:///home/iotedge/Certificates/device.key.pem"
    dynamic_reprovisioning: true
    always_reprovision_on_startup: false

certificates:
   device_ca_cert: "file:///home/iotedge/Certificates/device-ca.cert.pem"
   device_ca_pk: "file:///home/iotedge/Certificates/device-ca.key.pem"
   trusted_ca_certs: "file:///home/iotedge/Certificates/root.cert.pem"
   auto_generated_ca_lifetime_days: 1800

I tested it again today and I'm getting the same result:

sudo systemctl restart iotedge
# no rm certs this time
sudo journalctl -f -n 100

iotedged logs

Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Starting Azure IoT Edge Security Daemon
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Version - 1.0.10.2
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Using config file: /etc/iotedge/config.yaml
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Configuring certificates...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Configuring the Device CA certificate using "/home/iotedge/Certificates/device-ca.cert.pem".
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Configuring the Device private key using "/home/iotedge/Certificates/device-ca.key.pem".
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Configuring the trusted CA certificates using "/home/iotedge/Certificates/root.cert.pem".
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Finished configuring provisioning environment variables and certificates.
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Initializing hsm...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Finished initializing hsm.
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Initializing hsm X509 interface...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Finished initializing hsm X509 interface...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Provisioning edge device...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Starting provisioning edge device via X509 provisioning...
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [INFO] - Starting DPS registration with scope_id "xxx", registration_id "device1"
Jan 11 09:18:38 device1-server iotedged[16393]: 2021-01-11T08:18:38Z [DBUG] - [edgelet_http::client] Empty token source for request PUT xxx/registrations/device1/register
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [DBUG] - [edgelet_http::client] Empty token source for request GET xxx/registrations/device1/operations/4.2ccd682af5298751.9f91fc16-35e0-459c-8c1f-c9ba49371490
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - DPS registration assigned device "device1" in hub "xxx.azure-devices.net"
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Restoring device credentials from backup
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Device registration is unchanged in Azure and matches local provisioning backup.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Successful DPS provisioning.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Finished provisioning edge device.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Initializing the module runtime...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Initializing module runtime...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Using runtime network id azure-iot-edge
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Successfully initialized module runtime
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Finished initializing the module runtime.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Stopping all modules...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [DBUG] - [edgelet_docker::runtime] Listing modules...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [DBUG] - [edgelet_docker::runtime] Successfully listed modules
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Stopping module edgeHub...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Stopping module xxx...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Stopping module edgeAgent...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Finished stopping modules.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Detecting if configuration file has changed...
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - No change to configuration file detected.
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Edge issuer CA expiration date: 2030-05-30T09:00:42Z
Jan 11 09:18:49 device1-server iotedged[16393]: 2021-01-11T08:18:49Z [INFO] - Obtaining workload CA failed. Triggering reconfiguration
...
after that it removes all modules and downloads them again

Maybe using X509 instead of symmetric key is the culprit here?

What I would expect is that the Obtaining workload CA failed. Triggering reconfiguration message doesn't appear and the modules do not get downloaded again after a restart.

[arsing]

Maybe using X509 instead of symmetric key is the culprit here?

I cannot reproduce with DPS-X.509 provisioning either.

The behavior is the same no matter the value of always_reprovision_on_startup.

Yes, that is what I suspected.

[eustacea]

Adding @lfitchett.

[niravjprabtani]

Is there any fix for the mentioned issue ?

I am also getting the same issue whenever I restart the iotedge service. It reconfigures the modules and container.

[ribeach]

We are facing the same issue.
The problem occurs across all of our test devices (iotedged: 1.0.9, 1.0.10, 1.1.0*, OS: Debian 9, Debian 10, Raspberry OS, arch: armhf, armv64)

[florianbader]

@nyanzebra: I'm a bit confused. Does your PR fix this bug? Do you know when this will get released? Can we expect a patch for 1.1 or is it going to be in 1.2?

[niravjprabtani]

@nyanzebra: I'm a bit confused. Does your PR fix this bug? Do you know when this will get released? Can we expect a patch for 1.1 or is it going to be in 1.2?

I am also wondering when it will get released?

[domdeger]

This issue occurs for us as well at least since iotedged 1.0.9 on Debian 10 armhf. Pretty annoying since it adds to the start up time and kills the device when booted offline.
From what I understand iotedge should be capable of running without continuous internet connection.

[nyanzebra]

Hi Everyone, this closing of issue is likely a mistake on my part for accidentally linking the wrong thing for my PR that is for an entirely different feature. This is just a DPS issue, sorry for any confusion from my part! Reopening now :)

[niravjprabtani]

Is there any plan to get it fixed? it is more than 9 months and we don't have any update on this.

[darobs]

I attempted to reproduce this with 1.1 on an ARM32 using test certificates based on @florianbader's comment here - copied the yaml and filled in my own values. No luck, everything worked as expected. Is there something I missed when I set this up?

[florianbader]

Thanks to @veyalla and @darobs I managed to fix the problem for me. The issue was that I was creating a device CA which didn't contained the whole chain (root -> intermediate -> device CA) which cause the "Obtaining workflow CA failed" error message.
After fixing the device CA chain it worked as expected so I'm closing this issue.