search

Azure / iotedge

The IoT Edge OSS project
MIT License
1.45k stars 458 forks source link

HSM problems and IoT Hub connectivity test problems #5893

Open Suizi11 opened 2 years ago

Suizi11 commented 2 years ago

Expected Behavior

No error logs in the security daemon and successful connection check in the edgeAgent module.

Current Behavior

Error log in the security daemon and problem during connection check in the edgeAgent module.

Steps to Reproduce

Provide a detailed set of steps to reproduce the bug.

  1. Start iotedged
  2. Everything works fine for a few days
  3. Suddenly, the errors in the logs below occur.

Context (Environment)

Output of iotedge check

Click here ``` 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: certificates - Warning The device CA cert will expire within the next 90 days, at 2021-12-17 02:34:00 UTC. Renew the certificate before this date to retain functionality. See https://aka.ms/iotedge-prod-checklist-certs for best practices. √ 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 21 check(s) succeeded. 3 check(s) raised warnings. Re-run with --verbose for more details. ```

Device Information

Runtime Versions

Server: Engine: Version: 3.0.8 API version: 1.40 (minimum version 1.12) Go version: go1.12.10 Git commit: adfac69 Built: Wed Oct 23 17:54:47 2019 OS/Arch: linux/amd64 Experimental: false containerd: Version: v1.2.10 GitCommit: b34a5c8af56e510852c35414db4c1f4fa6172339 runc: Version: 1.0.0-rc8+dev GitCommit: 3e425f80a8c931f88e6d94a8c831b9d5aa481657 docker-init: Version: 0.18.0 GitCommit: fec3683


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

## Logs
<!--
Please share as many logs as possible. This will help debugging
Follow [diagnostic steps](https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot#standard-diagnostic-steps) to help extract useful information.
Don't forget to remove any connection string information!
-->

<details>
<summary>aziot-edged logs</summary>

Dec 06 09:40:59 iotedged[3139609]: 2021-12-06T09:40:59Z [INFO] - Checking edge runtime status Dec 06 09:40:59 iotedged[3139609]: 2021-12-06T09:40:59Z [INFO] - Edge runtime is running. Dec 06 09:41:00 iotedged[3139609]: 2021-12-06T09:41:00Z [INFO] - [mgmt] - - - [2021-12-06 09:41:00.172604555 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:05 iotedged[3139609]: 2021-12-06T09:41:05Z [INFO] - [mgmt] - - - [2021-12-06 09:41:05.209781196 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:10 iotedged[3139609]: 2021-12-06T09:41:10Z [INFO] - [mgmt] - - - [2021-12-06 09:41:10.250878261 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:14 iotedged[3139609]: 2021-12-06T09:41:14Z [INFO] - [work] - - - [2021-12-06 09:41:14.994130894 UTC] "POST /modules/%24edgeAgent/genid/637686149462566588/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 188 "-" "-" auth_id(-) Dec 06 09:41:15 iotedged[3139609]: 2021-12-06T09:41:15Z [INFO] - [mgmt] - - - [2021-12-06 09:41:15.293896478 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:15 iotedged[3139609]: 9:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:40:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE Dec 06 09:41:15 iotedged[3139609]: 2021-12-06T09:40:14Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:14 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE Dec 06 09:41:15 iotedged[3139609]: 2021-12-06T09:41:14Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:15 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:15 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:15 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication. Dec 06 09:41:15 iotedged[3139609]: Error: Time:Mon Dec 6 09:41:15 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to t<6>2021-12-06T09:41:15Z [INFO] - [work] - - - [2021-12-06 09:41:15.358> Dec 06 09:41:20 iotedged[3139609]: 2021-12-06T09:41:20Z [INFO] - [mgmt] - - - [2021-12-06 09:41:20.334790396 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:25 iotedged[3139609]: 2021-12-06T09:41:25Z [INFO] - [mgmt] - - - [2021-12-06 09:41:25.381628205 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-) Dec 06 09:41:30 iotedged[3139609]: 2021-12-06T09:41:30Z [INFO] - [mgmt] - - - [2021-12-06 09:41:30.418750067 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5044 "-" "-" auth_id(-)

</details>

<details>
<summary>edge-agent logs</summary>

Dec 06 09:42:37 2a087ef97ce6[32225]: <6> 2021-12-06 09:42:37.680 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint bec0ddfe-9681-4151-ac51-3d623f5ea07a/DataAgent/command and 0 messages from message store. Dec 06 09:42:42 2a087ef97ce6[32225]: <4> 2021-12-06 09:42:42.500 +00:00 [WRN] - Error calling IotHub for connectivity test Dec 06 09:42:42 2a087ef97ce6[32225]: Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadCommunicationException- Message:Error calling SignAsync: Module not found Dec 06 09:42:42 2a087ef97ce6[32225]: caused by: Signing error occurred. Dec 06 09:42:42 2a087ef97ce6[32225]: caused by: An error occurred in the key store. Dec 06 09:42:42 2a087ef97ce6[32225]: caused by: HSM failure Dec 06 09:42:42 2a087ef97ce6[32225]: caused by: HSM API failure occurred: 478, StatusCode:404, at: at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.HandleException(Exception ex, String operation) in /home/vsts/work/1/s/edge-uti> Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func1 func, String operation) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 79 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.WorkloadClient.SignAsync(String keyId, String algorithm, String data) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2019_01_> Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Util.ClientTokenProvider.GetTokenAsync(Option1 ttl) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/ClientTokenProvider.cs:line 62 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.AuthenticationWithTokenRefresh.GetTokenAsync(String iotHub) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsTokenProvider.GetTokenAsync(Uri namespaceAddress, String appliesTo, String[] requiredClaims) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Amqp.TaskHelpers.EndAsyncResult(IAsyncResult asyncResult) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Amqp.IteratorAsyncResult1.StepCallback(IAsyncResult result) Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a) Dec 06 09:42:42 2a087ef97ce6[32225]: at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization) Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass23_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext() Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func1 asyncOperation) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>cDisplayClass33_0.<b0>d.MoveNext() Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>cDisplayClass25_0.<b0>d.MoveNext() Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Client.InternalClient.UpdateReportedPropertiesAsync(TwinCollection reportedProperties) Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>cDisplayClass30_0.<b0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClie> Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func1 func, String operation, Boolean useForConnectivityCheck) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudPr> Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func1 func, String operation, Boolean useForConnectivityCheck) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudPr> Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 213 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 213 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.<>cDisplayClass22_0.<b0>d.MoveNext() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.c> Dec 06 09:42:42 2a087ef97ce6[32225]: --- End of stack trace from previous location where exception was thrown --- Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 72 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager.ConnectivityChecker.Check() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceConnectivityManager.cs:line 220 Dec 06 09:42:42 2a087ef97ce6[32225]: at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.DeviceConnectivityManager.CheckConnectivity() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/DeviceConnectivityManager.cs:line 190 Dec 06 09:42:45 2a087ef97ce6[32225]: <6> 2021-12-06 09:42:45.180 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint bec0ddfe-9681-4151-ac51-3d623f5ea07a/ProtocolAbstraction/command Dec 06 09:42:45 2a087ef97ce6[32225]: <6> 2021-12-06 09:42:45.182 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint bec0ddfe-9681-4151-ac51-3d623f5ea07a/ProtocolAbstraction/command and 0 messages from message store. Dec 06 09:42:45 2a087ef97ce6[32225]: <6> 2021-12-06 09:42:45.182 +00:00 [INF] - Started task to cleanup processed and stale messages for endpoint bec0ddfe-9681-4151-ac51-3d623f5ea07a/DataAgent/commandResponse Dec 06 09:42:45 2a087ef97ce6[32225]: <6> 2021-12-06 09:42:45.182 +00:00 [INF] - Cleaned up 0 messages from queue for endpoint bec0ddfe-9681-4151-ac51-3d623f5ea07a/DataAgent/commandResponse and 0 messages from message store.

</details>

<details>
<summary>edge-hub logs</summary>

not relevant


</details>

## Additional Information
Please provide any additional information that may be helpful in understanding the issue.
nyanzebra commented 2 years ago

Hi, I don't have a CentOs Stream 8, but does it have a TPM resource manager? One possibility is an out of date fw: https://github.com/Azure/azure-utpm-c/issues/9... but let us know if this version of centos has a kernel manager for TPM. I will try to get an image and use a local machine (Azure doesn't seem to have a VM image I can use) and repro. Will update here as I make progress.

nyanzebra commented 2 years ago

Could you from HOST OS of Centos, run this: ls /dev/tpmrm*?

Suizi11 commented 2 years ago

@nyanzebra thank you

When I list all tpm* devices I get following result:

$ ll /dev/tpm*
crw-------. 1 iotedge root  10,   224 Dec  4 01:59 /dev/tpm0
crw-------. 1 iotedge tss  253, 65536 Dec  4 01:59 /dev/tpmrm0

JFI, my kernel release and version is:

$ uname -rv
4.18.0-338.el8.x86_64 #1 SMP Fri Aug 27 17:32:14 UTC 2021

After a restart of the runtime everything was working fine again. Saw this errors the first time after updating to version 1.1.8 of iotedged a few days ago. Before, in version 1.1.3, I never saw this issue. After the update I followed following steps: https://docs.microsoft.com/en-us/azure/iot-edge/how-to-provision-devices-at-scale-linux-tpm?view=iotedge-2018-06&preserve-view=true&tabs=physical-device#give-iot-edge-access-to-the-tpm Initially I forgot to give also access to tpmrm0, after granting access iotedged provisioned successfully as in 1.1.3.

nyanzebra commented 2 years ago

@Suizi11 I take it everything is working correctly then for you? Does this issue need to remain open?

Suizi11 commented 2 years ago

@nyanzebra of course this issue has to remain open, because it must be solved ... or what is the solution of MS if this issue happens on 1000 devices?

However, issue occurs again now. Restarted on 03-12 and saw it in the logs on 07-12 again (oldest available log, probably problem happened already before). I'll check it daily when it happens again and come back here as soon it happens again.

Nevertheless, the problem is not a big deal at one device, but not acceptable on 1000 devices.

Suizi11 commented 2 years ago

@nyanzebra as posted above, a restart seems to solve the issue, however, the restart now seems to work, after 4-5 minutes following errors occured (no sensitive data because it's a staging device): Maybe a certificate/store problem (see log at Dec 09 10:34:24)

The error block (a few times Plain text is not trustworthy.) occurred 3 times in total, then everything is working again, for now (waiting for original problem).

Dec 09 10:33:19 iotedged[3011953]: 2021-12-09T10:33:19Z [INFO] - [mgmt] - - - [2021-12-09 10:33:19.731727131 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:24 iotedged[3011953]: 2021-12-09T10:33:24Z [INFO] - [mgmt] - - - [2021-12-09 10:33:24.739341025 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:29 iotedged[3011953]: 2021-12-09T10:33:29Z [INFO] - [mgmt] - - - [2021-12-09 10:33:29.747915710 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:29 iotedged[3011953]: 2021-12-09T10:33:29Z [INFO] - Checking edge runtime status
Dec 09 10:33:30 iotedged[3011953]: 2021-12-09T10:33:30Z [INFO] - Edge runtime is running.
Dec 09 10:33:34 iotedged[3011953]: 2021-12-09T10:33:34Z [INFO] - [mgmt] - - - [2021-12-09 10:33:34.755995977 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:37 iotedged[3011953]: 2021-12-09T10:33:37Z [INFO] - Querying system resources...
Dec 09 10:33:39 iotedged[3011953]: 2021-12-09T10:33:39Z [INFO] - [mgmt] - - - [2021-12-09 10:33:39.057975210 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 4156 "-" "-" auth_id(-)
Dec 09 10:33:39 iotedged[3011953]: 2021-12-09T10:33:39Z [INFO] - [mgmt] - - - [2021-12-09 10:33:39.766187644 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:44 iotedged[3011953]: 2021-12-09T10:33:44Z [INFO] - [mgmt] - - - [2021-12-09 10:33:44.777552260 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:49 iotedged[3011953]: 2021-12-09T10:33:49Z [INFO] - [mgmt] - - - [2021-12-09 10:33:49.785335501 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
Dec 09 10:33:50 iotedged[3011953]: 2021-12-09T10:33:50Z [INFO] - [work] - - - [2021-12-09 10:33:50.095461390 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 3293 "-" "-" auth_id(-)
Dec 09 10:33:50 iotedged[3011953]: 2021-12-09T10:33:50Z [INFO] - [mgmt] - - - [2021-12-09 10:33:50.998784966 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 322 "-" "-" auth_id(-)
Dec 09 10:33:51 iotedged[3011953]: 2021-12-09T10:33:51Z [INFO] - [mgmt] - - - [2021-12-09 10:33:51.389478343 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
Dec 09 10:33:51 iotedged[3011953]: 2021-12-09T10:33:51Z [INFO] - [mgmt] - - - [2021-12-09 10:33:51.643253479 UTC] "POST /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-)
Dec 09 10:33:51 iotedged[3011953]: 2021-12-09T10:33:51Z [INFO] - [mgmt] - - - [2021-12-09 10:33:51.655237716 UTC] "PUT /identities/blobstorageoniotedge?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
Dec 09 10:33:52 iotedged[3011953]: 2021-12-09T10:33:52Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.1...
Dec 09 10:33:52 iotedged[3011953]: 2021-12-09T10:33:52Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.1
Dec 09 10:33:52 iotedged[3011953]: 2021-12-09T10:33:52Z [INFO] - [mgmt] - - - [2021-12-09 10:33:52.895380896 UTC] "POST /modules/edgeAgent/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Updating and starting module edgeAgent
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Removing module edgeAgent...
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Stopping listener for module edgeAgent
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Stopping listener for module edgeAgent
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [WARN] - Could not remove socket with uri unix:///var/lib/iotedge/mnt/edgeAgent.sock
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [WARN] - The workload manager encountered an error
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [WARN] -         caused by: No such file or directory (os error 2)
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Successfully removed module edgeAgent
Dec 09 10:33:53 iotedged[3011953]: 2021-12-09T10:33:53Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-agent:1.1...
Dec 09 10:33:55 iotedged[3011953]: 2021-12-09T10:33:55Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.1
Dec 09 10:33:55 iotedged[3011953]: 2021-12-09T10:33:55Z [INFO] - Creating module edgeAgent...
Dec 09 10:33:55 iotedged[3011953]: 2021-12-09T10:33:55Z [INFO] - Starting new listener for module edgeAgent
Dec 09 10:33:55 iotedged[3011953]: 2021-12-09T10:33:55Z [INFO] - Listener  edgeAgent already started, removing old listener
Dec 09 10:33:55 iotedged[3011953]: 2021-12-09T10:33:55Z [INFO] - Listening on unix:///var/lib/iotedge/mnt/edgeAgent.sock with 1 thread for workload API.
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [INFO] - Successfully created module edgeAgent
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [INFO] - Starting module edgeAgent
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [INFO] - Starting module edgeAgent...
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [INFO] - Successfully started module edgeAgent
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [INFO] - [mgmt] - - - [2021-12-09 10:33:56.699443269 UTC] "PUT /modules/edgeAgent?api-version=2020-07-07&start=true HTTP/1.1" 200 OK 1552 "-" "-" auth_id(-)
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [ERR!] - server connection error: (unknown)
Dec 09 10:33:56 iotedged[3011953]: 2021-12-09T10:33:56Z [ERR!] - error writing a body to connection: Broken pipe (os error 32)
Dec 09 10:33:58 iotedged[3011953]: 2021-12-09T10:33:58Z [INFO] - [work] - - - [2021-12-09 10:33:58.250512818 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1092 "-" "-" auth_id(-)
Dec 09 10:33:59 iotedged[3011953]: 2021-12-09T10:33:59Z [INFO] - Querying system info...
Dec 09 10:33:59 iotedged[3011953]: none
Dec 09 10:33:59 iotedged[3011953]: 2021-12-09T10:33:59Z [INFO] - Successfully queried system info
Dec 09 10:33:59 iotedged[3011953]: 2021-12-09T10:33:59Z [INFO] - [mgmt] - - - [2021-12-09 10:33:59.285691001 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 295 "-" "-" auth_id(-)
Dec 09 10:34:00 iotedged[3011953]: 2021-12-09T10:34:00Z [INFO] - [work] - - - [2021-12-09 10:34:00.937539318 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [INFO] - Querying system info...
Dec 09 10:34:01 iotedged[3011953]: none
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [INFO] - Successfully queried system info
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [INFO] - [mgmt] - - - [2021-12-09 10:34:01.226022294 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 295 "-" "-" auth_id(-)
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:01 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:01 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:01 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [INFO] - [work] - - - [2021-12-09 10:34:01.486412042 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/decrypt?api-version=2020-07-07 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:01 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:01 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:01 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:01 iotedged[3011953]: 2021-12-09T10:34:01Z [INFO] - [work] - - - [2021-12-09 10:34:01.559441078 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/decrypt?api-version=2020-07-07 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:04 iotedged[3011953]: 2021-12-09T10:34:04Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:04 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:04 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:04 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:04 iotedged[3011953]: 2021-12-09T10:34:04Z [INFO] - [work] - - - [2021-12-09 10:34:04.636187899 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/decrypt?api-version=2020-07-07 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:07 iotedged[3011953]: 2021-12-09T10:34:07Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:07 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:07 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:07 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:07 iotedged[3011953]: 2021-12-09T10:34:07Z [INFO] - [work] - - - [2021-12-09 10:34:07.719599935 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/decrypt?api-version=2020-07-07 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:07 iotedged[3011953]: 2021-12-09T10:34:07Z [INFO] - [mgmt] - - - [2021-12-09 10:34:07.891889304 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 651 "-" "-" auth_id(-)
Dec 09 10:34:08 iotedged[3011953]: 2021-12-09T10:34:08Z [INFO] - [work] - - - [2021-12-09 10:34:08.223585272 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 3293 "-" "-" auth_id(-)
Dec 09 10:34:08 iotedged[3011953]: 2021-12-09T10:34:08Z [INFO] - [mgmt] - - - [2021-12-09 10:34:08.510690876 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 420 "-" "-" auth_id(-)
Dec 09 10:34:08 iotedged[3011953]: 2021-12-09T10:34:08Z [INFO] - [mgmt] - - - [2021-12-09 10:34:08.852274875 UTC] "PUT /identities/WebServer?api-version=2020-07-07 HTTP/1.1" 200 OK 99 "-" "-" auth_id(-)
Dec 09 10:34:08 iotedged[3011953]: 2021-12-09T10:34:08Z [INFO] - [mgmt] - - - [2021-12-09 10:34:08.970042784 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
Dec 09 10:34:09 iotedged[3011953]: 2021-12-09T10:34:09Z [INFO] - [mgmt] - - - [2021-12-09 10:34:09.094000627 UTC] "PUT /identities/blobstorageoniotedge?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
Dec 09 10:34:09 iotedged[3011953]: 2021-12-09T10:34:09Z [INFO] - Pulling image ntuity.azurecr.io/web-server-module:151.amd64...
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Successfully pulled image ntuity.azurecr.io/web-server-module:151.amd64
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Creating module WebServer...
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Starting new listener for module WebServer
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Listening on unix:///var/lib/iotedge/mnt/WebServer.sock with 1 thread for workload API.
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Successfully created module WebServer
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - [mgmt] - - - [2021-12-09 10:34:10.809376884 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1696 "-" "-" auth_id(-)
Dec 09 10:34:10 iotedged[3011953]: 2021-12-09T10:34:10Z [INFO] - Starting module WebServer...
Dec 09 10:34:11 iotedged[3011953]: 2021-12-09T10:34:11Z [INFO] - Successfully started module WebServer
Dec 09 10:34:11 iotedged[3011953]: 2021-12-09T10:34:11Z [INFO] - [mgmt] - - - [2021-12-09 10:34:11.844054005 UTC] "POST /modules/WebServer/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 09 10:34:11 iotedged[3011953]: 2021-12-09T10:34:11Z [INFO] - Pulling image mcr.microsoft.com/azureiotedge-hub:1.1...
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Successfully pulled image mcr.microsoft.com/azureiotedge-hub:1.1
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Creating module edgeHub...
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Starting new listener for module edgeHub
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Listening on unix:///var/lib/iotedge/mnt/edgeHub.sock with 1 thread for workload API.
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Successfully created module edgeHub
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - [mgmt] - - - [2021-12-09 10:34:12.727463453 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1249 "-" "-" auth_id(-)
Dec 09 10:34:12 iotedged[3011953]: 2021-12-09T10:34:12Z [INFO] - Starting module edgeHub...
Dec 09 10:34:13 iotedged[3011953]: 2021-12-09T10:34:13Z [INFO] - Successfully started module edgeHub
Dec 09 10:34:13 iotedged[3011953]: 2021-12-09T10:34:13Z [INFO] - [mgmt] - - - [2021-12-09 10:34:13.754873130 UTC] "POST /modules/edgeHub/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 09 10:34:13 iotedged[3011953]: 2021-12-09T10:34:13Z [INFO] - Pulling image mcr.microsoft.com/azure-blob-storage:1.4...
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - [work] - - - [2021-12-09 10:34:15.124413925 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/certificate/server?api-version=2019-01-30 HTTP/1.1" 201 Created 9200 "-" "-" auth_id(-)
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Successfully pulled image mcr.microsoft.com/azure-blob-storage:1.4
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Creating module blobstorageoniotedge...
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Starting new listener for module blobstorageoniotedge
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Listening on unix:///var/lib/iotedge/mnt/blobstorageoniotedge.sock with 1 thread for workload API.
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Successfully created module blobstorageoniotedge
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - [mgmt] - - - [2021-12-09 10:34:15.760566421 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1194 "-" "-" auth_id(-)
Dec 09 10:34:15 iotedged[3011953]: 2021-12-09T10:34:15Z [INFO] - Starting module blobstorageoniotedge...
Dec 09 10:34:16 iotedged[3011953]: 2021-12-09T10:34:16Z [INFO] - [work] - - - [2021-12-09 10:34:16.032659064 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1092 "-" "-" auth_id(-)
Dec 09 10:34:16 iotedged[3011953]: 2021-12-09T10:34:16Z [INFO] - Successfully started module blobstorageoniotedge
Dec 09 10:34:16 iotedged[3011953]: 2021-12-09T10:34:16Z [INFO] - [mgmt] - - - [2021-12-09 10:34:16.566523964 UTC] "POST /modules/blobstorageoniotedge/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Dec 09 10:34:16 iotedged[3011953]: 2021-12-09T10:34:16Z [INFO] - [work] - - - [2021-12-09 10:34:16.660732571 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:16 iotedged[3011953]: 2021-12-09T10:34:16Z [INFO] - [work] - - - [2021-12-09 10:34:16.664009441 UTC] "POST /modules/%24edgeAgent/genid/637746424451283477/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 3293 "-" "-" auth_id(-)
Dec 09 10:34:17 iotedged[3011953]: 2021-12-09T10:34:17Z [INFO] - [work] - - - [2021-12-09 10:34:17.114540888 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:17 iotedged[3011953]: 2021-12-09T10:34:17Z [INFO] - [work] - - - [2021-12-09 10:34:17.217291603 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "-" auth_id(-)
Dec 09 10:34:18 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:18 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:18 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:18 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:18 iotedged[3011953]: 2021-12-09T10:34:18Z [INFO] - [work] - - - [2021-12-09 10:34:18.371512176 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:18 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:18 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:18 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:18 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:18 iotedged[3011953]: 2021-12-09T10:34:18Z [INFO] - [work] - - - [2021-12-09 10:34:18.451945714 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:21 iotedged[3011953]: 2021-12-09T10:34:21Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:21 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:21 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:21 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:21 iotedged[3011953]: 2021-12-09T10:34:21Z [INFO] - [work] - - - [2021-12-09 10:34:21.483116299 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:22 iotedged[3011953]: 2021-12-09T10:34:22Z [INFO] - [mgmt] - - - [2021-12-09 10:34:22.141497210 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2934 "-" "-" auth_id(-)
Dec 09 10:34:22 iotedged[3011953]: 2021-12-09T10:34:22Z [INFO] - [work] - - - [2021-12-09 10:34:22.230488605 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:22 iotedged[3011953]: 2021-12-09T10:34:22Z [INFO] - [work] - - - [2021-12-09 10:34:22.353678974 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:24 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [INFO] - [work] - - - [2021-12-09 10:34:24.545977871 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:24 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [INFO] - [work] - - - [2021-12-09 10:34:24.623927538 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:27:17Z [INFO] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:01Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:04Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:07Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:07Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:15Z [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 $edgeHub637746424451283477server
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:15Z [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: $edgeHub637746424451283477server
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:15Z [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 $edgeHub637746424451283477server
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:15Z [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 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:21Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:21Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot<3>2021-12-09T10:34:24Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:24 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:24 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:24 iotedged[3011953]: 2021-12-09T10:34:24Z [INFO] - [work] - - - [2021-12-09 10:34:24.671626505 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:27 iotedged[3011953]: 2021-12-09T10:34:27Z [INFO] - [work] - - - [2021-12-09 10:34:27.370315311 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:27 iotedged[3011953]: 2021-12-09T10:34:27Z [INFO] - [work] - - - [2021-12-09 10:34:27.500651485 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:27 iotedged[3011953]: 2021-12-09T10:34:27Z [INFO] - [mgmt] - - - [2021-12-09 10:34:27.506339571 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2934 "-" "-" auth_id(-)
Dec 09 10:34:27 iotedged[3011953]: 2021-12-09T10:34:27Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:27 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:27 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:27 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:27 iotedged[3011953]: 2021-12-09T10:34:27Z [INFO] - [work] - - - [2021-12-09 10:34:27.722400910 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:29 iotedged[3011953]: 2021-12-09T10:34:29Z [INFO] - Checking edge runtime status
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [INFO] - Edge runtime is running.
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:30 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [INFO] - [work] - - - [2021-12-09 10:34:30.792808541 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:30 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [INFO] - [work] - - - [2021-12-09 10:34:30.860843314 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:30 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:30 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:30 iotedged[3011953]: 2021-12-09T10:34:30Z [INFO] - [work] - - - [2021-12-09 10:34:30.917678659 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:32 iotedged[3011953]: 2021-12-09T10:34:32Z [INFO] - [work] - - - [2021-12-09 10:34:32.516346881 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:32 iotedged[3011953]: 2021-12-09T10:34:32Z [INFO] - [mgmt] - - - [2021-12-09 10:34:32.549195276 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2934 "-" "-" auth_id(-)
Dec 09 10:34:32 iotedged[3011953]: 2021-12-09T10:34:32Z [INFO] - [work] - - - [2021-12-09 10:34:32.639681656 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:33 iotedged[3011953]: 2021-12-09T10:34:33Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:33 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:33 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:33 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:33 iotedged[3011953]: 2021-12-09T10:34:33Z [INFO] - [work] - - - [2021-12-09 10:34:33.990741517 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:37 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [work] - - - [2021-12-09 10:34:37.050378340 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:37 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [work] - - - [2021-12-09 10:34:37.102320329 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:37 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:37 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [work] - - - [2021-12-09 10:34:37.146852954 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [mgmt] - - - [2021-12-09 10:34:37.589392785 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2934 "-" "-" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [work] - - - [2021-12-09 10:34:37.658026997 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:37 iotedged[3011953]: 2021-12-09T10:34:37Z [INFO] - [work] - - - [2021-12-09 10:34:37.767665929 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:39 iotedged[3011953]: 2021-12-09T10:34:39Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:39 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:39 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:39 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:39 iotedged[3011953]: 2021-12-09T10:34:39Z [INFO] - [work] - - - [2021-12-09 10:34:39.851227433 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [INFO] - [mgmt] - - - [2021-12-09 10:34:42.629903648 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 2934 "-" "-" auth_id(-)
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [INFO] - [work] - - - [2021-12-09 10:34:42.786861362 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1092 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [INFO] - [work] - - - [2021-12-09 10:34:42.904683054 UTC] "POST /modules/WebServer/genid/637746428312116844/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:42 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:42 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:42 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [INFO] - [work] - - - [2021-12-09 10:34:42.948667206 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:42 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:42 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:42 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:42 iotedged[3011953]: 2021-12-09T10:34:42Z [INFO] - [work] - - - [2021-12-09 10:34:42.997143671 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:43 iotedged[3011953]: -hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:27Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:27Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:30Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:33Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:33Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:37Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:39Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:39Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:42Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:43Z [ERR!] (/project/edgelet/hsm-sys/a<3>2021-12-09T10:34:43Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:43 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:43 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:43 iotedged[3011953]:         caused by: HSM API failure occurred: 431
Dec 09 10:34:43 iotedged[3011953]: 2021-12-09T10:34:43Z [INFO] - [work] - - - [2021-12-09 10:34:43.059204866 UTC] "POST /modules/%24edgeHub/genid/637746424451283477/decrypt?api-version=2019-01-30 HTTP/1.1" 500 Internal Server Error 151 "-" "-" auth_id(-)
Dec 09 10:34:46 iotedged[3011953]: 2021-12-09T10:34:46Z [ERR!] - Internal server error: Could not decrypt
Dec 09 10:34:46 iotedged[3011953]:         caused by: An error occurred in the key store.
Dec 09 10:34:46 iotedged[3011953]:         caused by: HSM failure
Dec 09 10:34:46 iotedged[3011953]:         caused by: HSM API failure occurred: 431
nyanzebra commented 2 years ago

@Suizi11 so to clear, the issue regarding TPM still occurs? Just happens after a while post-restart?

nyanzebra commented 2 years ago

@Suizi11 from speaking with my team the HSM failures should be benign as this could be caused by a redeploy making the module enc key different. But this can be safely ignored.

Suizi11 commented 2 years ago

@nyanzebra yes there's still an error - just happening after a while after restarting iotedged

I've updated now to iotedged 1.1.8, and also edgeAgent and edgeHub have latest tag 1.1.

Only edgeAgent and edgeHub modules are running but not connected to the cloud, all custom modules cannot connect anymore to the edgeHub. I've about 8 devices where this happens (= every gateway where I've updated to 1.1.8).

Logs of iotedged:

Dec 10 09:10:59 iotedged[3235]: 2021-12-10T09:10:59Z [INFO] - Edge runtime is running.
Dec 10 09:11:00 iotedged[3235]: 2021-12-10T09:11:00Z [INFO] - [mgmt] - - - [2021-12-10 09:11:00.718636997 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4728 "-" "-" auth_id(-)
Dec 10 09:11:05 iotedged[3235]: 2021-12-10T09:11:05Z [INFO] - [mgmt] - - - [2021-12-10 09:11:05.757770643 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4728 "-" "-" auth_id(-)
Dec 10 09:11:10 iotedged[3235]: 2021-12-10T09:11:10Z [INFO] - [mgmt] - - - [2021-12-10 09:11:10.793501676 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4728 "-" "-" auth_id(-)
Dec 10 09:11:15 iotedged[3235]: 2021-12-10T09:11:15Z [INFO] - [mgmt] - - - [2021-12-10 09:11:15.832135478 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4728 "-" "-" auth_id(-)
Dec 10 09:11:20 iotedged[3235]: 2021-12-10T09:11:20Z [INFO] - [mgmt] - - - [2021-12-10 09:11:20.868119566 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 4728 "-" "-" auth_id(-)
Dec 10 09:11:24 iotedged[3235]: data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:02Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:02Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:05Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:09Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:09Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:12Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:15Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:15Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_enc_openssl_key.c:decrypt_v1:341) Verification of plain text failed. Plain text is not trustworthy.
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T08:26:18Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/edge_hsm_client_crypto.c:decrypt_data:430) Error decrypting data. Error code 342
Dec 10 09:11:24 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 10 09:11:24 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 10 09:11:24 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 10 09:11:24 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/a<6>2021-12-10T09:11:24Z [INFO] - [work] - - - [2021-12-10 09:11:24.254343261 UTC] "POST /modules/WebServer/genid/637686151276029120/sign?api-version=2018-06-2>
Dec 10 09:11:24 iotedged[3235]: 2021-12-10T09:11:24Z [INFO] - [work] - - - [2021-12-10 09:11:24.954987714 UTC] "POST /modules/Modbus/genid/637686153052341335/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 188 "-" "azure-iot-device/1.17.7" auth_id(-)
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:25Z [INFO] - [work] - - - [2021-12-10 09:11:25.527767439 UTC] "POST /modules/%24edgeHub/genid/637686149462566588/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4944 "-" "-" auth_id(-)
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:25Z [INFO] - [work] - - - [2021-12-10 09:11:25.583105191 UTC] "POST /modules/%24edgeHub/genid/637686149462566588/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4969 "-" "-" auth_id(-)
Dec 10 09:11:25 iotedged[3235]: zure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:24 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:24Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:25 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:25 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:25 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:11:25 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 10 09:11:25 iotedged[3235]: Error: Time:Fri Dec 10 09:1<6>2021-12-10T09:11:25Z [INFO] - [work] - - - [2021-12-10 09:11:25.648871802 UTC] "POST /modules/DataAgent/genid/637686153053122782/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 188 "-" "azure->
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:25Z [INFO] - [work] - - - [2021-12-10 09:11:25.649010374 UTC] "POST /modules/%24edgeHub/genid/637686149462566588/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4948 "-" "-" auth_id(-)
Dec 10 09:11:25 iotedged[3235]: 2021-12-10T09:11:25Z [INFO] - [work] - - - [2021-12-10 09:11:25.706367732 UTC] "POST /modules/%24edgeHub/genid/637686149462566588/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 5321 "-" "-" auth_id(-)

Logs of edgeAgent:

<6> 2021-12-10 11:36:56.270 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...
<6> 2021-12-10 11:36:56.577 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<4> 2021-12-10 11:36:56.920 +00:00 [WRN] - Error creating a device-to-cloud connection
System.AggregateException: One or more errors occurred. (Error calling SignAsync: Module not found
    caused by: Signing error occurred.
    caused by: An error occurred in the key store.
    caused by: HSM failure
    caused by: HSM API failure occurred: 478, StatusCode: 404) (Error calling SignAsync: Module not found
    caused by: Signing error occurred.
    caused by: An error occurred in the key store.
    caused by: HSM failure
    caused by: HSM API failure occurred: 478, StatusCode: 404)
 ---> Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmComunicationException: Error calling SignAsync: Module not found
    caused by: Signing error occurred.
    caused by: An error occurred in the key store.
    caused by: HSM failure
    caused by: HSM API failure occurred: 478, StatusCode: 404
   at Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmSignatureProvider.SignAsync(String moduleId, String generationId, String data)
   at Microsoft.Azure.Devices.Client.HsmAuthentication.ModuleAuthenticationWithHsm.SafeCreateNewToken(String iotHub, Int32 suggestedTimeToLive)
   at Microsoft.Azure.Devices.Client.AuthenticationWithTokenRefresh.GetTokenAsync(String iotHub)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsTokenProvider.GetTokenAsync(Uri namespaceAddress, String appliesTo, String[] requiredClaims)
   at Microsoft.Azure.Amqp.TaskHelpers.EndAsyncResult(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.IteratorAsyncResult`1.StepCallback(IAsyncResult result)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass23_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass33_0.<<OpenInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.CreateAndOpenSdkModuleClient(UpstreamProtocol upstreamProtocol, ConnectionStatusChangesHandler statusChangedHandler) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 221
   at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.<>c__DisplayClass19_1.<<CreateSdkModuleClient>b__2>d.MoveNext() in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 185
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Util.Fallback.ExecuteAsync[T](Func`1[] options)
   --- End of inner exception stack trace ---
 ---> (Inner Exception #1) Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmComunicationException: Error calling SignAsync: Module not found
    caused by: Signing error occurred.
    caused by: An error occurred in the key store.
    caused by: HSM failure
    caused by: HSM API failure occurred: 478, StatusCode: 404
   at Microsoft.Azure.Devices.Client.HsmAuthentication.HttpHsmSignatureProvider.SignAsync(String moduleId, String generationId, String data)
   at Microsoft.Azure.Devices.Client.HsmAuthentication.ModuleAuthenticationWithHsm.SafeCreateNewToken(String iotHub, Int32 suggestedTimeToLive)
   at Microsoft.Azure.Devices.Client.AuthenticationWithTokenRefresh.GetTokenAsync(String iotHub)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsTokenProvider.GetTokenAsync(Uri namespaceAddress, String appliesTo, String[] requiredClaims)
   at Microsoft.Azure.Amqp.TaskHelpers.EndAsyncResult(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.IteratorAsyncResult`1.StepCallback(IAsyncResult result)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass23_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass33_0.<<OpenInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
   at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.CreateAndOpenSdkModuleClient(UpstreamProtocol upstreamProtocol, ConnectionStatusChangesHandler statusChangedHandler) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 221
   at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.<>c__DisplayClass19_1.<<CreateSdkModuleClient>b__3>d.MoveNext() in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 191
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.Azure.Devices.Edge.Util.Fallback.ExecuteAsync[T](Func`1[] options)<---
<6> 2021-12-10 11:36:58.277 +00:00 [INF] - Module 'ProtocolAbstraction' scheduled to restart after 05m:00s (02m:51s left).
<6> 2021-12-10 11:36:58.277 +00:00 [INF] - Module 'Modbus' scheduled to restart after 05m:00s (02m:57s left).
<6> 2021-12-10 11:36:58.277 +00:00 [INF] - Module 'DataAgent' scheduled to restart after 05m:00s (03m:14s left).
<6> 2021-12-10 11:36:58.277 +00:00 [INF] - Module 'WebServer' scheduled to restart after 05m:00s (03m:37s left).
Suizi11 commented 2 years ago

@nyanzebra if I log /var/log/messages I can see following error/problem:

Dec 14 06:29:49 kernel: tpm tpm0: tpm2_load_context: failed with a TPM error 0x01CB
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 iotedged[2045]: or: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:28:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE
Dec 14 06:29:49 iotedged[2045]: 2021-12-14T06:28:49Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:678 Get Capability failure
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:44 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:SignData Line:377 Hashing token data failed TPM_RC_COMMAND_CODE
Dec 14 06:29:49 iotedged[2045]: 2021-12-14T06:29:44Z [ERR!] (/project/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_client_tpm_device.c:hsm_client_tpm_sign_data:477) Failure signing data from hash
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:write_data_to_tpm Line:110 Failure writing data to tpm: 14:Bad address.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_comm_linux.c Func:tpm_comm_submit_command Line:390 Failure setting locality to TPM
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_SendCommand Line:1187 submitting command to TPM Communication.
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_DispatchCmd Line:1102 Sending command to tpm -2144861951.
Dec 14 06:29:49 kernel: tpm tpm0: tpm2_load_context: failed with a TPM error 0x01CB
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:49 iotedged[2045]: Error: Time:Tue Dec 14 06:29:49 2021 File:/project/edgelet/hsm-sys/azure-iot-hsm-c/deps/utpm/src/tpm_codec.c Func:TSS_GetTpmProperty Line:6<6>2021-12-14T06:29:49Z [INFO] - [work] - - - [2021-12-14 06:29:49.834141753 UTC] "POST /modules/%24edgeAgent/genid/637696426571094051/sign?api-version=2018-06-28 HTTP/1.1" 404 Not Found 188 "-" "-" auth_id(-)
Dec 14 06:29:50 kernel: tpm tpm0: tpm2_load_context: failed with a TPM error 0x01CB
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: tpm2_load_context: failed with a TPM error 0x01CB
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
Dec 14 06:29:50 kernel: tpm tpm0: A TPM error (139) occurred flushing context
nyanzebra commented 2 years ago

Just to convey here what is being conveyed in a separate channel: so, several things to update on:

  1. From what we support from Supported operating systems, container engines - Azure IoT Edge | Microsoft Docs Centos 8 (linux/stream) is an unsupported os, so there might complications that we are not aware of with trying to use centos 8 stream. There shouldn't be too much of a difference between centos 7, but just want to point this out :)
  2. From looking into the tpm code and the failures; it appears to be failing on the handle for the provisioned tpm key, are there any other process(es) using tpm key?
  3. Is it possible to narrow down bad version? As it appears 1.1.3 works, so just curious if there are other versions that have been tried or if willing to try to see when the issue begins... from 1.1.4 onwards?
Suizi11 commented 2 years ago

It' happens with every version of iotedged.

I've found a workaround for the problem. In the documentation it's mentioned that also iotedge user must be owner of the /dev/tpmrm0 device. https://docs.microsoft.com/de-de/azure/iot-edge/how-to-provision-devices-at-scale-linux-tpm?view=iotedge-2018-06&preserve-view=true&tabs=physical-device#give-iot-edge-access-to-the-tpm

If I skip this, everything works as expected. I don't know why the iotede user even needs access to the resource manager of the TPM module. Maybe the documentation is wrong with regards to CentOS.

nyanzebra commented 2 years ago

@Suizi11 We are working on an update to documentation for getting iotedge working alongside TPM, will post that updated docs here as soon as they are available :)

github-actions[bot] commented 2 years ago

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

rahulrana-XOM commented 2 years ago

Hi, has there been any update on this?

EDIT: I tried Suizi11's workaround and the runtime is working as expected.