search

Azure / iotedge

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

iotedged and edgeAgent fail to retreive provisionning status after "long" shutdown #3982

Closed FabGre closed 3 years ago

FabGre commented 3 years ago

Hi there. We are working on an iotedge device which has a specific "low-power" behaviour : it has to be off most of the time and start-up only a few times per days and for a few minutes to collect all its sensors (with different custom edge modules), sent data to iotHub, then shutdown.

With the last 1.0.10 iotedge version, we have a strange behaviour seems to be relative to the "off" duration. When our edge device stays off during 2 hours, edgeAgent seems to trig a device reprovisionning just after backup restore and start (in the logs : iotedged[668]: 2020-11-16T10:03:55Z [INFO] - [mgmt] - - - [2020-11-16 10:03:55.145755273 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)). The problem is that our 4G connection is not set-up at this time and iotedged will try 5 times then fails and stop, we also to be able to work offline so we dont want this reprovisionning.

When the "off" duration is 15 min or 1h, edgeAgent successes to load provionning information from backup and edge stack successes to start without trigging a reprovisionning.

This problem appears with iotedge version 1.0.10 We are provisionned using dps with the following configuration in config.yaml

  always_reprovision_on_startup: false
  dynamic_reprovisioning: true

We have tried to set dynamic_reprovisioning: false to disable the reprovisionning command, We have the following logs:

2020-11-17T14:49:48.172430+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:48Z [INFO] - [work] - - - [2020-11-17 14:49:48.170488646 UTC] "POST /modules/%24edgeAgent/genid/637410305934936752/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
2020-11-17T14:49:49.158085+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:49Z [INFO] - Querying system info...
2020-11-17T14:49:49.315685+00:00 phycore-stm32mp1-peach iotedged[697]: none
2020-11-17T14:49:49.317157+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:49Z [INFO] - Successfully queried system info
2020-11-17T14:49:49.318437+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:49Z [INFO] - [mgmt] - - - [2020-11-17 14:49:49.315265564 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 363 "-" "-" auth_id(-)
2020-11-17T14:49:49+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:49.700 +00:00 [INF] - Registering request handler UploadModuleLogs
2020-11-17T14:49:49+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:49.704 +00:00 [INF] - Registering request handler GetModuleLogs
2020-11-17T14:49:49+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:49.707 +00:00 [INF] - Registering request handler UploadSupportBundle
2020-11-17T14:49:49+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:49.710 +00:00 [INF] - Registering request handler RestartModule
2020-11-17T14:49:50.543492+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:50Z [INFO] - [work] - - - [2020-11-17 14:49:50.541546231 UTC] "POST /modules/%24edgeAgent/genid/637410305934936752/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5724 "-" "-" auth_id(-)
2020-11-17T14:49:51.883936+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:51Z [INFO] - [mgmt] - - - [2020-11-17 14:49:51.881974065 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <3> 2020-11-17 14:49:51.910 +00:00 [ERR] - Device client threw non-transient exception during setup
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: The specified SAS token is expired.)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:  ---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: The specified SAS token is expired.
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Amqp.AsyncResult`1.End(IAsyncResult asyncResult)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Amqp.AmqpCbsLink.EndSendToken(IAsyncResult result)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Amqp.AmqpCbsLink.<>c__DisplayClass4_0.<SendTokenAsync>b__1(IAsyncResult a)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: --- End of stack trace from previous location where exception was thrown ---
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    --- End of inner exception stack trace ---
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTCbsLink.SendTokenAsync(ICbsTokenProvider tokenProvider, Uri namespaceAddress, String audience, String resource, String[] requiredClaims, TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpAuthenticationRefresher.InitLoopAsync(TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.CreateRefresherAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass23_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: --- End of stack trace from previous location where exception was thrown ---
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass33_0.<<OpenInternalAsync>b__0>d.MoveNext()
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: --- End of stack trace from previous location where exception was thrown ---
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync()
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    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 216
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.<>c__DisplayClass19_0.<<CreateSdkModuleClient>b__0>d.MoveNext() in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 169
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: --- End of stack trace from previous location where exception was thrown ---
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:    at Microsoft.Azure.Devices.Edge.Agent.IoTHub.ModuleClientProvider.CreateSdkModuleClientWithRetry(ConnectionStatusChangesHandler statusChangedHandler) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/ModuleClientProvider.cs:line 151
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:52.247 +00:00 [INF] - Termination requested, initiating shutdown.
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:52.248 +00:00 [INF] - Waiting for cleanup to finish
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:52.613 +00:00 [INF] - Closing module management agent.
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:52.632 +00:00 [INF] - Initiating shutdown cleanup.
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <6> 2020-11-17 14:49:52.651 +00:00 [INF] - Stopping all modules...
2020-11-17T14:49:53.078600+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:53Z [INFO] - [mgmt] - - - [2020-11-17 14:49:53.076580232 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 3636 "-" "-" auth_id(-)

Expected Behavior

edge stack can start up offline when DPS was already done.

Current Behavior

see above.

Steps to Reproduce

Context (Environment)

Output of iotedge check

Click here ``` ```

Device Information

Runtime Versions

iotedged [1.0.10]: Edge Agent [1.0.10]: Edge Hub [1.0.10]: Note: when using Windows containers on Windows, run docker -H npipe:////./pipe/iotedge_moby_engine version instead

Logs

iotedged logs ``` Nov 16 10:03:23 phycore-stm32mp1-peach systemd[1]: Started Azure IoT Edge daemon. Nov 16 10:03:23 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:23Z [INFO] - Starting Azure IoT Edge Security Daemon Nov 16 10:03:23 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:23Z [INFO] - Version - 1.0.10 Nov 16 10:03:23 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:23Z [INFO] - Using config file: /etc/iotedge/config.yaml Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Configuring /usr/local/iotedge as the home directory. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Configuring certificates... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Transparent gateway certificates not found, operating in quick start mode... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Finished configuring provisioning environment variables and certificates. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Initializing hsm... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Finished initializing hsm. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Provisioning edge device... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Starting provisioning edge device via symmetric key... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Attempting to restore provisioning backup... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Restoring device credentials from backup Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Successful DPS provisioning. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Finished provisioning edge device. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Initializing the module runtime... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Initializing module runtime... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Using runtime network id azure-iot-edge Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Successfully initialized module runtime Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Finished initializing the module runtime. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping all modules... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module master... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module samus... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module daisy... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module toad... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module edgeHub... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Stopping module edgeAgent... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module master Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module samus Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module daisy Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module edgeHub Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module edgeAgent Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - Could not stop module toad Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [WARN] - caused by: Target of operation already in this state Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Finished stopping modules. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Detecting if configuration file has changed... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - No change to configuration file detected. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Edge issuer CA expiration date: 2021-02-12T12:44:09Z Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Obtaining workload CA succeeded. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Starting management API... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Starting workload API... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Starting watchdog with 60 second frequency... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Checking edge runtime status Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Edge runtime status is failed, starting module now... Nov 16 10:03:24 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:24Z [INFO] - Starting module edgeAgent... Nov 16 10:03:28 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:28Z [INFO] - Successfully started module edgeAgent Nov 16 10:03:36 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:36Z [INFO] - [work] - - - [2020-11-16 10:03:36.920118764 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) Nov 16 10:03:42 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:42Z [INFO] - Querying system info... Nov 16 10:03:42 phycore-stm32mp1-peach iotedged[668]: none Nov 16 10:03:42 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:42Z [INFO] - Successfully queried system info Nov 16 10:03:42 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:42Z [INFO] - [mgmt] - - - [2020-11-16 10:03:42.382019516 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 362 "-" "-" auth_id(-) Nov 16 10:03:51 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:51Z [INFO] - [work] - - - [2020-11-16 10:03:51.187245104 UTC] "POST /modules/%24edgeAgent/genid/637381734766668589/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) Nov 16 10:03:52 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:52Z [INFO] - Querying system info... Nov 16 10:03:52 phycore-stm32mp1-peach iotedged[668]: none Nov 16 10:03:52 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:52Z [INFO] - Successfully queried system info Nov 16 10:03:52 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:52Z [INFO] - [mgmt] - - - [2020-11-16 10:03:52.444170896 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 362 "-" "-" auth_id(-) Nov 16 10:03:53 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:53Z [INFO] - [work] - - - [2020-11-16 10:03:53.703015355 UTC] "POST /modules/%24edgeAgent/genid/637381734766668589/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5720 "-" "-" auth_id(-) Nov 16 10:03:55 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:55Z [INFO] - [mgmt] - - - [2020-11-16 10:03:55.145755273 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-) Nov 16 10:03:55 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:55Z [INFO] - Edge runtime will stop because of the device reprovisioning signal. Nov 16 10:03:55 phycore-stm32mp1-peach iotedged[668]: 2020-11-16T10:03:55Z [ERR!] - The device has been de-provisioned ```
Full syslog logs ``` 2020-11-14T23:05:34.211020+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting Azure IoT Edge Security Daemon 2020-11-14T23:05:34.211878+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Version - 1.0.10 2020-11-14T23:05:34.213775+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Using config file: /etc/iotedge/config.yaml 2020-11-14T23:05:34.284062+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Configuring /usr/local/iotedge as the home directory. 2020-11-14T23:05:34.285137+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Configuring certificates... 2020-11-14T23:05:34.285791+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Transparent gateway certificates not found, operating in quick start mode... 2020-11-14T23:05:34.286882+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Finished configuring provisioning environment variables and certificates. 2020-11-14T23:05:34.287518+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Initializing hsm... 2020-11-14T23:05:34.322080+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Finished initializing hsm. 2020-11-14T23:05:34.444321+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Provisioning edge device... 2020-11-14T23:05:34.445012+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting provisioning edge device via symmetric key... 2020-11-14T23:05:34.447554+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Attempting to restore provisioning backup... 2020-11-14T23:05:34.452801+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Restoring device credentials from backup 2020-11-14T23:05:34.461617+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Successful DPS provisioning. 2020-11-14T23:05:34.465620+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Finished provisioning edge device. 2020-11-14T23:05:34.467557+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Initializing the module runtime... 2020-11-14T23:05:34.468856+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Initializing module runtime... 2020-11-14T23:05:34.470111+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Using runtime network id azure-iot-edge 2020-11-14T23:05:34.664502+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Successfully initialized module runtime 2020-11-14T23:05:34.665446+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Finished initializing the module runtime. 2020-11-14T23:05:34.666104+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping all modules... 2020-11-14T23:05:34.726725+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module master... 2020-11-14T23:05:34.727563+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module samus... 2020-11-14T23:05:34.728247+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module daisy... 2020-11-14T23:05:34.728829+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module toad... 2020-11-14T23:05:34.730114+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module edgeHub... 2020-11-14T23:05:34.731141+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Stopping module edgeAgent... 2020-11-14T23:05:34.737711+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module master 2020-11-14T23:05:34.738472+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.739744+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module daisy 2020-11-14T23:05:34.740765+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.741718+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module edgeAgent 2020-11-14T23:05:34.743022+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.744251+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module samus 2020-11-14T23:05:34.746190+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.747054+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module edgeHub 2020-11-14T23:05:34.747660+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.749300+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - Could not stop module toad 2020-11-14T23:05:34.750004+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [WARN] - #011caused by: Target of operation already in this state 2020-11-14T23:05:34.750684+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Finished stopping modules. 2020-11-14T23:05:34.751420+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Detecting if configuration file has changed... 2020-11-14T23:05:34.752116+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - No change to configuration file detected. 2020-11-14T23:05:34.754030+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Edge issuer CA expiration date: 2021-02-12T12:44:09Z 2020-11-14T23:05:34.773461+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Obtaining workload CA succeeded. 2020-11-14T23:05:34.795321+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting management API... 2020-11-14T23:05:34.830908+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting workload API... 2020-11-14T23:05:34.843761+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting watchdog with 60 second frequency... 2020-11-14T23:05:34.848212+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Listening on fd://iotedge.mgmt.socket/ with 1 thread for management API. 2020-11-14T23:05:34.849028+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Listening on fd://iotedge.socket/ with 1 thread for workload API. 2020-11-14T23:05:34.850087+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Checking edge runtime status 2020-11-14T23:05:34.925308+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Edge runtime status is failed, starting module now... 2020-11-14T23:05:34.926066+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] - Starting module edgeAgent... 2020-11-14T23:05:34.999565+00:00 phycore-stm32mp1-peach kernel: [ 21.689463] br-dcdad82bab55: port 1(veth0d5646a) entered blocking state 2020-11-14T23:05:34.999656+00:00 phycore-stm32mp1-peach kernel: [ 21.689573] br-dcdad82bab55: port 1(veth0d5646a) entered disabled state 2020-11-14T23:05:34.999668+00:00 phycore-stm32mp1-peach kernel: [ 21.690398] device veth0d5646a entered promiscuous mode 2020-11-14T23:05:34.999677+00:00 phycore-stm32mp1-peach kernel: [ 21.691362] IPv6: ADDRCONF(NETDEV_UP): veth0d5646a: link is not ready 2020-11-14T23:05:35.011118+00:00 phycore-stm32mp1-peach systemd-udevd[675]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. 2020-11-14T23:05:35.012043+00:00 phycore-stm32mp1-peach systemd-udevd[675]: Could not generate persistent MAC address for veth99a5642: No such file or directory 2020-11-14T23:05:35.017494+00:00 phycore-stm32mp1-peach systemd-udevd[674]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. 2020-11-14T23:05:35.023495+00:00 phycore-stm32mp1-peach systemd-udevd[674]: Could not generate persistent MAC address for veth0d5646a: No such file or directory 2020-11-14T23:05:35.119376+00:00 phycore-stm32mp1-peach kernel: [ 21.811982] IPv6: ADDRCONF(NETDEV_UP): veth99a5642: link is not ready 2020-11-14T23:05:35.119461+00:00 phycore-stm32mp1-peach kernel: [ 21.812844] IPv6: ADDRCONF(NETDEV_UP): veth99a5642: link is not ready 2020-11-14T23:05:35.119473+00:00 phycore-stm32mp1-peach kernel: [ 21.812904] IPv6: ADDRCONF(NETDEV_CHANGE): veth99a5642: link becomes ready 2020-11-14T23:05:35.119482+00:00 phycore-stm32mp1-peach kernel: [ 21.813165] IPv6: ADDRCONF(NETDEV_CHANGE): veth0d5646a: link becomes ready 2020-11-14T23:05:35.119490+00:00 phycore-stm32mp1-peach kernel: [ 21.813368] br-dcdad82bab55: port 1(veth0d5646a) entered blocking state 2020-11-14T23:05:35.119499+00:00 phycore-stm32mp1-peach kernel: [ 21.813385] br-dcdad82bab55: port 1(veth0d5646a) entered forwarding state 2020-11-14T23:05:35.119506+00:00 phycore-stm32mp1-peach kernel: [ 21.813941] IPv6: ADDRCONF(NETDEV_CHANGE): br-dcdad82bab55: link becomes ready 2020-11-14T23:05:35.420319+00:00 phycore-stm32mp1-peach nm-dispatcher: req:2 'up' [veth0d5646a]: new request (0 scripts) 2020-11-14T23:05:35.421088+00:00 phycore-stm32mp1-peach nm-dispatcher: req:2 'up' [veth0d5646a]: completed: no scripts 2020-11-14T23:05:35.480195+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Joining mDNS multicast group on interface veth99a5642.IPv6 with address fe80::26c3:3c52:1ca4:5986. 2020-11-14T23:05:35.482111+00:00 phycore-stm32mp1-peach avahi-daemon[244]: New relevant interface veth99a5642.IPv6 for mDNS. 2020-11-14T23:05:35.482880+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Registering new address record for fe80::26c3:3c52:1ca4:5986 on veth99a5642.*. 2020-11-14T23:05:35.556055+00:00 phycore-stm32mp1-peach dockerd[356]: time="2020-11-14T23:05:35Z" level=info msg="shim containerd-shim started" address="/containerd-shim/moby/a448cabdc59e5a7f1dde36062d86fb45c9aaf3ae4210a6a648fad297cec7b094/shim.sock" debug=false module="containerd/tasks" pid=680 2020-11-14T23:05:35.692698+00:00 phycore-stm32mp1-peach dhclient: DHCPDISCOVER on veth99a5642 to 255.255.255.255 port 67 interval 7 2020-11-14T23:05:37.076158+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Joining mDNS multicast group on interface br-dcdad82bab55.IPv6 with address fe80::42:d5ff:feb0:9a8a. 2020-11-14T23:05:37.077034+00:00 phycore-stm32mp1-peach avahi-daemon[244]: New relevant interface br-dcdad82bab55.IPv6 for mDNS. 2020-11-14T23:05:37.077730+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Registering new address record for fe80::42:d5ff:feb0:9a8a on br-dcdad82bab55.*. 2020-11-14T23:05:38.071204+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Interface veth99a5642.IPv6 no longer relevant for mDNS. 2020-11-14T23:05:38.071959+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Leaving mDNS multicast group on interface veth99a5642.IPv6 with address fe80::26c3:3c52:1ca4:5986. 2020-11-14T23:05:38.073430+00:00 phycore-stm32mp1-peach dhclient: receive_packet failed on veth99a5642: Network is down 2020-11-14T23:05:38.139437+00:00 phycore-stm32mp1-peach kernel: [ 24.830836] br-dcdad82bab55: port 1(veth0d5646a) entered disabled state 2020-11-14T23:05:38.144720+00:00 phycore-stm32mp1-peach avahi-daemon[244]: Withdrawing address record for fe80::26c3:3c52:1ca4:5986 on veth99a5642. 2020-11-14T23:05:38.154212+00:00 phycore-stm32mp1-peach dhclient: Received signal 15, initiating shutdown. 2020-11-14T23:05:38.159396+00:00 phycore-stm32mp1-peach kernel: [ 24.847867] eth0: renamed from veth99a5642 2020-11-14T23:05:38.209316+00:00 phycore-stm32mp1-peach kernel: [ 24.903465] br-dcdad82bab55: port 1(veth0d5646a) entered blocking state 2020-11-14T23:05:38.209400+00:00 phycore-stm32mp1-peach kernel: [ 24.903490] br-dcdad82bab55: port 1(veth0d5646a) entered forwarding state 2020-11-14T23:05:38+00:00 localhost edgeAgent[356]: 2020-11-14 23:05:38 +00:00 Starting Edge Agent 2020-11-14T23:05:38.716197+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:38Z [INFO] - Successfully started module edgeAgent 2020-11-14T23:05:38+00:00 localhost edgeAgent[356]: 2020-11-14 23:05:38 +00:00 Changing ownership of storage folder: /iotedge/storage//edgeAgent to 1000 2020-11-14T23:05:38+00:00 localhost edgeAgent[356]: 2020-11-14 23:05:38 +00:00 Changing ownership of management socket: /var/run/iotedge/mgmt.sock 2020-11-14T23:05:40+00:00 localhost edgeAgent[356]: 2020-11-14 23:05:40.273 +00:00 Edge Agent Main() 2020-11-14T23:05:41.012756+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: starting ssh (count 12) 2020-11-14T23:05:41.014229+00:00 phycore-stm32mp1-peach autossh[354]: starting ssh (count 12) 2020-11-14T23:05:41.015720+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: ssh child pid is 839 2020-11-14T23:05:41.027119+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: check on child 839 2020-11-14T23:05:41.028587+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: set alarm for 581 secs 2020-11-14T23:05:41.029828+00:00 phycore-stm32mp1-peach autossh[354]: ssh child pid is 839 2020-11-14T23:05:41.031110+00:00 phycore-stm32mp1-peach autossh[354]: autossh[839]: execing /usr/bin/ssh 2020-11-14T23:05:41.032199+00:00 phycore-stm32mp1-peach autossh[354]: check on child 839 2020-11-14T23:05:41.038768+00:00 phycore-stm32mp1-peach autossh[354]: set alarm for 581 secs 2020-11-14T23:05:41.043444+00:00 phycore-stm32mp1-peach autossh[839]: execing /usr/bin/ssh 2020-11-14T23:05:41.044136+00:00 phycore-stm32mp1-peach autossh[354]: ssh: Could not resolve hostname reverse.obr.rtower.io: Temporary failure in name resolution 2020-11-14T23:05:41.044779+00:00 phycore-stm32mp1-peach autossh[354]: check on child 839 2020-11-14T23:05:41.045540+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: check on child 839 2020-11-14T23:05:41.046158+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: ssh exited with error status 255; restarting ssh 2020-11-14T23:05:41.046819+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: expired child, returning 1 2020-11-14T23:05:41.047428+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: checking for grace period, tries = 12 2020-11-14T23:05:41.048016+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: sleeping for grace time 9 secs 2020-11-14T23:05:41.048659+00:00 phycore-stm32mp1-peach autossh[354]: ssh exited with error status 255; restarting ssh 2020-11-14T23:05:41.049572+00:00 phycore-stm32mp1-peach autossh[354]: expired child, returning 1 2020-11-14T23:05:41.050328+00:00 phycore-stm32mp1-peach autossh[354]: checking for grace period, tries = 12 2020-11-14T23:05:41.051029+00:00 phycore-stm32mp1-peach autossh[354]: sleeping for grace time 9 secs 2020-11-14T23:05:43+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:43.206 +00:00 [INF] - Initializing Edge Agent. 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:45.697 +00:00 [INF] - Version - 1.0.10.35691904 (c6350db898b2bd7abe1d50a340a1b1a91e72127d) 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:45.707 +00:00 [INF] - 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: █████╗ ███████╗██╗ ██╗██████╗ ███████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ 2020-11-14T23:05:45+00:00 localhost edgeAgent[356]: 2020-11-14T23:05:46+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:46.352 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false} 2020-11-14T23:05:47.140003+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:47Z [INFO] - [work] - - - [2020-11-14 23:05:47.137847513 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1944 "-" "-" auth_id(-) 2020-11-14T23:05:47+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:47.943 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:02/12/2021 12:44:09] to Root 2020-11-14T23:05:48.338185+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'... 2020-11-14T23:05:48.339090+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: qmi_wwan 2020-11-14T23:05:48.343853+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Checking version info (10 retries)... 2020-11-14T23:05:48.490067+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] QMI Device supports 33 services: 2020-11-14T23:05:48.491048+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] ctl (1.5) 2020-11-14T23:05:48.491933+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] wds (1.67) 2020-11-14T23:05:48.492887+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] dms (1.0) 2020-11-14T23:05:48.493850+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] nas (1.25) 2020-11-14T23:05:48.494815+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] qos (1.12) 2020-11-14T23:05:48.495857+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] wms (1.10) 2020-11-14T23:05:48.496800+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] auth (1.3) 2020-11-14T23:05:48.498375+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] at (1.2) 2020-11-14T23:05:48.499982+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] voice (2.1) 2020-11-14T23:05:48.500943+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] cat2 (2.24) 2020-11-14T23:05:48.501936+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] uim (1.46) 2020-11-14T23:05:48.502824+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] pbm (1.4) 2020-11-14T23:05:48.503758+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] test (1.0) 2020-11-14T23:05:48.504765+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] loc (2.0) 2020-11-14T23:05:48.505786+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] sar (1.0) 2020-11-14T23:05:48.506817+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] ims (1.0) 2020-11-14T23:05:48.507792+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] ts (1.0) 2020-11-14T23:05:48.508863+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] tmd (1.0) 2020-11-14T23:05:48.509979+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] wda (1.16) 2020-11-14T23:05:48.510999+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] csvt (1.1) 2020-11-14T23:05:48.512028+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] imsa (1.0) 2020-11-14T23:05:48.513060+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] coex (1.0) 2020-11-14T23:05:48.514064+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] pdc (1.0) 2020-11-14T23:05:48.515072+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] rfrpe (1.0) 2020-11-14T23:05:48.516131+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] dsd (1.0) 2020-11-14T23:05:48.517134+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0x2d] (1.0) 2020-11-14T23:05:48.518127+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0x30] (1.0) 2020-11-14T23:05:48.519249+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0x32] (1.0) 2020-11-14T23:05:48.520259+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0x36] (1.0) 2020-11-14T23:05:48.521333+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0xe6] (1.0) 2020-11-14T23:05:48.522375+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0xe7] (1.0) 2020-11-14T23:05:48.523421+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0xeb] (1.0) 2020-11-14T23:05:48.524426+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] unknown [0xed] (1.0) 2020-11-14T23:05:48.525363+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Reading expected data format from: /sys/class/net/wwan0/qmi/raw_ip 2020-11-14T23:05:48.526344+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:48.527370+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'wda' (version 1.16) client with ID '1' 2020-11-14T23:05:48.554394+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Writing expected data format to: /sys/class/net/wwan0/qmi/raw_ip 2020-11-14T23:05:48.556081+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Reading expected data format from: /sys/class/net/wwan0/qmi/raw_ip 2020-11-14T23:05:48.562956+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:48.563795+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Releasing 'wda' client with flags 'release-cid'... 2020-11-14T23:05:48.564690+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Unregistered 'wda' client with ID '1' 2020-11-14T23:05:48.586347+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'dms' (version 1.0) client with ID '1' 2020-11-14T23:05:48.595959+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:48.651501+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'nas' (version 1.25) client with ID '3' 2020-11-14T23:05:48.657422+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:48.682274+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'wms' (version 1.10) client with ID '3' 2020-11-14T23:05:48.686612+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:48.714089+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'uim' (version 1.46) client with ID '2' 2020-11-14T23:05:49+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:49.945 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics 2020-11-14T23:05:50.044390+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: starting ssh (count 13) 2020-11-14T23:05:50.045804+00:00 phycore-stm32mp1-peach autossh[354]: starting ssh (count 13) 2020-11-14T23:05:50.060681+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: ssh child pid is 893 2020-11-14T23:05:50.061994+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: check on child 893 2020-11-14T23:05:50.063196+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: set alarm for 572 secs 2020-11-14T23:05:50.064534+00:00 phycore-stm32mp1-peach autossh[354]: ssh child pid is 893 2020-11-14T23:05:50.071567+00:00 phycore-stm32mp1-peach autossh[354]: autossh[893]: execing /usr/bin/ssh 2020-11-14T23:05:50.090518+00:00 phycore-stm32mp1-peach autossh[354]: check on child 893 2020-11-14T23:05:50.091855+00:00 phycore-stm32mp1-peach autossh[354]: set alarm for 572 secs 2020-11-14T23:05:50.094784+00:00 phycore-stm32mp1-peach autossh[893]: execing /usr/bin/ssh 2020-11-14T23:05:50.109739+00:00 phycore-stm32mp1-peach autossh[354]: ssh: Could not resolve hostname reverse.obr.rtower.io: Temporary failure in name resolution 2020-11-14T23:05:50.110978+00:00 phycore-stm32mp1-peach autossh[354]: check on child 893 2020-11-14T23:05:50.112296+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: check on child 893 2020-11-14T23:05:50.113362+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: ssh exited with error status 255; restarting ssh 2020-11-14T23:05:50.114393+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: expired child, returning 1 2020-11-14T23:05:50.125045+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: checking for grace period, tries = 13 2020-11-14T23:05:50.126408+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: sleeping for grace time 12 secs 2020-11-14T23:05:50.143428+00:00 phycore-stm32mp1-peach autossh[354]: ssh exited with error status 255; restarting ssh 2020-11-14T23:05:50.144820+00:00 phycore-stm32mp1-peach autossh[354]: expired child, returning 1 2020-11-14T23:05:50.146116+00:00 phycore-stm32mp1-peach autossh[354]: checking for grace period, tries = 13 2020-11-14T23:05:50.147344+00:00 phycore-stm32mp1-peach autossh[354]: sleeping for grace time 12 secs 2020-11-14T23:05:52+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:52.189 +00:00 [INF] - Updating performance metrics every 05m:00s 2020-11-14T23:05:52+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:52.255 +00:00 [INF] - Started operation Get system resources 2020-11-14T23:05:52+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:52.277 +00:00 [INF] - Collecting metadata metrics 2020-11-14T23:05:52.376022+00:00 phycore-stm32mp1-peach wait-modem.sh[353]: Modem is up 2020-11-14T23:05:52.471019+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:52Z [INFO] - Querying system info... 2020-11-14T23:05:52.768214+00:00 phycore-stm32mp1-peach iotedged[654]: none 2020-11-14T23:05:52.769763+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:52Z [INFO] - Successfully queried system info 2020-11-14T23:05:52.770520+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:52Z [INFO] - [mgmt] - - - [2020-11-14 23:05:52.769347933 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 362 "-" "-" auth_id(-) 2020-11-14T23:05:52.975461+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Allocating new client ID... 2020-11-14T23:05:53.005403+00:00 phycore-stm32mp1-peach ModemManager[252]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '17' 2020-11-14T23:05:53+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:53.386 +00:00 [INF] - Set metadata metrics: 1.0.10.35691904 (c6350db898b2bd7abe1d50a340a1b1a91e72127d), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"armv7l","Version":"1.0.10","Provisioning":{"Type":"dps.symmetric_key","DynamicReprovisioning":true,"AlwaysReprovisionOnStartup":false},"ServerVersion":"19.03.2","KernelVersion":"4.19.9","OperatingSystem":"ST OpenSTLinux - Weston - obr -(A Yocto Project Based Distro) 2.6-snapshot-20201111 (thud)","NumCpus":2,"Virtualized":"no"}, True 2020-11-14T23:05:53.499833+00:00 phycore-stm32mp1-peach wait-modem.sh[353]: Connection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/5) 2020-11-14T23:05:53.528775+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.529971+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.530662+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.531272+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.531832+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.532450+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.546198+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.547489+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.549936+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.551199+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.552367+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.558271+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.559809+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.561119+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.562351+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.563574+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.576352+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.577212+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.577983+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.578658+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.579487+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.580149+00:00 phycore-stm32mp1-peach dnsmasq[365]: reading /etc/resolv.conf 2020-11-14T23:05:53.580734+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.8.8#53 2020-11-14T23:05:53.581237+00:00 phycore-stm32mp1-peach dnsmasq[365]: using nameserver 8.8.4.4#53 2020-11-14T23:05:53.582691+00:00 phycore-stm32mp1-peach dbus-daemon[249]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0 pid=303 comm="/usr/sbin/NetworkManager --no-daemon --log-level=E") 2020-11-14T23:05:53.639869+00:00 phycore-stm32mp1-peach systemd[1]: Starting Network Manager Script Dispatcher Service... 2020-11-14T23:05:53.671484+00:00 phycore-stm32mp1-peach systemd[1]: Started Modem Manager. 2020-11-14T23:05:53.702715+00:00 phycore-stm32mp1-peach systemd[1]: Reached target Multi-User System. 2020-11-14T23:05:53+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:53.716 +00:00 [INF] - Started operation Checkpoint Availability 2020-11-14T23:05:53.729486+00:00 phycore-stm32mp1-peach dbus-daemon[249]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' 2020-11-14T23:05:53.766287+00:00 phycore-stm32mp1-peach nm-dispatcher: req:1 'up' [wwan0]: new request (0 scripts) 2020-11-14T23:05:53.767397+00:00 phycore-stm32mp1-peach systemd[1]: Starting Update UTMP about System Runlevel Changes... 2020-11-14T23:05:53.768099+00:00 phycore-stm32mp1-peach nm-dispatcher: req:1 'up' [wwan0]: completed: no scripts 2020-11-14T23:05:53.771128+00:00 phycore-stm32mp1-peach systemd[1]: Started Network Manager Script Dispatcher Service. 2020-11-14T23:05:53.772385+00:00 phycore-stm32mp1-peach nm-dispatcher: req:2 'connectivity-change': new request (0 scripts) 2020-11-14T23:05:53.773679+00:00 phycore-stm32mp1-peach nm-dispatcher: req:2 'connectivity-change': completed: no scripts 2020-11-14T23:05:53+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:53.794 +00:00 [INF] - Started operation refresh twin config 2020-11-14T23:05:53.864888+00:00 phycore-stm32mp1-peach systemd[1]: Started Update UTMP about System Runlevel Changes. 2020-11-14T23:05:53.908205+00:00 phycore-stm32mp1-peach systemd[1]: Startup finished in 1.205s (kernel) + 39.387s (userspace) = 40.592s. 2020-11-14T23:05:54+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:54.001 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only... 2020-11-14T23:05:58+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:58.212 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeAgent 2020-11-14T23:05:58+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:58.774 +00:00 [INF] - Started operation Metrics Scrape 2020-11-14T23:05:58+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:58.776 +00:00 [INF] - Started operation Metrics Upload 2020-11-14T23:05:58+00:00 localhost edgeAgent[356]: Scraping frequency: 01:00:00 2020-11-14T23:05:58+00:00 localhost edgeAgent[356]: Upload Frequency: 1.00:00:00 2020-11-14T23:06:01.304281+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:01Z [INFO] - [work] - - - [2020-11-14 23:06:01.302285562 UTC] "POST /modules/%24edgeAgent/genid/637381734766668589/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-) 2020-11-14T23:06:02.108814+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: starting ssh (count 14) 2020-11-14T23:06:02.110443+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: ssh child pid is 939 2020-11-14T23:06:02.120369+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: check on child 939 2020-11-14T23:06:02.121611+00:00 phycore-stm32mp1-peach autossh[354]: autossh[354]: set alarm for 560 secs 2020-11-14T23:06:02.122746+00:00 phycore-stm32mp1-peach autossh[354]: starting ssh (count 14) 2020-11-14T23:06:02.123989+00:00 phycore-stm32mp1-peach autossh[354]: autossh[939]: execing /usr/bin/ssh 2020-11-14T23:06:02.130665+00:00 phycore-stm32mp1-peach autossh[354]: ssh child pid is 939 2020-11-14T23:06:02.131916+00:00 phycore-stm32mp1-peach autossh[354]: check on child 939 2020-11-14T23:06:02.134874+00:00 phycore-stm32mp1-peach autossh[354]: set alarm for 560 secs 2020-11-14T23:06:02.137038+00:00 phycore-stm32mp1-peach autossh[939]: execing /usr/bin/ssh 2020-11-14T23:06:02.229697+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:02Z [INFO] - Querying system info... 2020-11-14T23:06:02.411109+00:00 phycore-stm32mp1-peach iotedged[654]: none 2020-11-14T23:06:02.413098+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:02Z [INFO] - Succesed systsfully queriem info 2020-11-14T23:06:02.414385+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:02Z [INFO] - [mgmt] - - - [2020-11-14 23:06:02.406375062 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 362 "-" "-" auth_id(-) 2020-11-14T23:06:02+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:06:02.773 +00:00 [INF] - Registering request handler UploadModuleLogs 2020-11-14T23:06:02+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:06:02.776 +00:00 [INF] - Registering request handler GetModuleLogs 2020-11-14T23:06:02+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:06:02.779 +00:00 [INF] - Registering request handler UploadSupportBundle 2020-11-14T23:06:02+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:06:02.782 +00:00 [INF] - Registering request handler RestartModule 2020-11-14T23:06:03.710956+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:03Z [INFO] - [work] - - - [2020-11-14 23:06:03.702246813 UTC] "POST /modules/%24edgeAgent/genid/637381734766668589/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5720 "-" "-" auth_id(-) 2020-11-14T23:06:05.204578+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:05Z [INFO] - [mgmt] - - - [2020-11-14 23:06:05.202690105 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-) 2020-11-14T23:06:05.205507+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:05Z [INFO] - Edge runtime will stop because of the device reprovisioning signal. 2020-11-14T23:06:05.237521+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:06:05Z [ERR!] - The device has been de-provisioned 2020-11-14T23:06:05.240880+00:00 phycore-stm32mp1-peach iotedged[654]: 2020-11-14T23:05:34Z [INFO] (/builds/yoshi-repo/build/tmp-glibc/work/cortexa7t2hf-neon-vfpv4-openstlinux_weston-linux-gnueabi/libiothsm-std/1.0.10-r0/iotedge-1.0.10/edgelet/hsm-sys/azure-iot-hsm-c/src/hsm_log.c:log_init:41) Initialized logging 2020-11-14T23:06:05.280814+00:00 phycore-stm32mp1-peach systemd[1]: iotedge.service: Main process exited, code=exited, status=154/n/a 2020-11-14T23:06:05.281803+00:00 phycore-stm32mp1-peach systemd[1]: iotedge.service: Failed with result 'exit-code'. 2020-11-14T23:06:05.509625+00:00 phycore-stm32mp1-peach systemd[1]: iotedge.service: Service RestartSec=100ms expired, scheduling restart. 2020-11-14T23:06:05.510562+00:00 phycore-stm32mp1-peach systemd[1]: iotedge.service: Scheduled restart job, restart counter is at 1. 2020-11-14T23:06:05.511490+00:00 phycore-stm32mp1-peach systemd[1]: Stopped Azure IoT Edge daemon. 2020-11-14T23:06:05.512340+00:00 phycore-stm32mp1-peach systemd[1]: Closed Azure IoT Edge daemon workload socket. 2020-11-14T23:06:05.519859+00:00 phycore-stm32mp1-peach systemd[1]: Stopping Azure IoT Edge daemon workload socket. 2020-11-14T23:06:05.527971+00:00 phycore-stm32mp1-peach systemd[1]: Starting Azure IoT Edge daemon workload socket. 2020-11-14T23:06:05.535264+00:00 phycore-stm32mp1-peach systemd[1]: Closed Azure IoT Edge daemon management socket. 2020-11-14T23:06:05.540727+00:00 phycore-stm32mp1-peach systemd[1]: Stopping Azure IoT Edge daemon management socket. 2020-11-14T23:06:05.548998+00:00 phycore-stm32mp1-peach systemd[1]: Starting Azure IoT Edge daemon management socket. 2020-11-14T23:06:05.589504+00:00 phycore-stm32mp1-peach systemd[1]: Listening on Azure IoT Edge daemon workload socket. 2020-11-14T23:06:05.590479+00:00 phycore-stm32mp1-peach systemd[1]: Listening on Azure IoT Edge daemon management socket. ```
edge-hub logs ``` ```

Additional Information

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

damonbarry commented 3 years ago

@FabGre In addition to the original 1.0.10 release, there have been two patch releases, 1.0.10.1 and 1.0.10.2. Can you confirm exactly which version of iotedged you're running? I ask because there were some updates to the provisioning code in these releases so it will help us figure out what's happening.

damonbarry commented 3 years ago

Also, what happened when you tried to set device_reprovisioning=false? I would expect that setting to solve your problem.

pcurt commented 3 years ago

We are using the last released version for our Yocto Thud: https://github.com/Azure/azure-iotedge/releases/download/1.0.10/iotedge-1.0.10.tar.gz I don't know if it is a 1.0.10.1 or 1.0.10.2 from the sources

The setting device_reprovisioning=false doesn't solve: because edeAgent crashes after "POST /device/reprovision" command (see the logs in the issue). So the boot sequence is longer and not very clean

damonbarry commented 3 years ago

Sorry...to clarify, the setting in config.yaml is dynamic_reprovisioning, not device_reprovisioning.

In the "full syslog logs" you provided, Edge agent reports this:

2020-11-14T23:05:53+00:00 localhost edgeAgent[356]: <6> 2020-11-14 23:05:53.386 +00:00 [INF] - Set metadata metrics: 1.0.10.35691904 (c6350db898b2bd7abe1d50a340a1b1a91e72127d), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"armv7l","Version":"1.0.10","Provisioning":{"Type":"dps.symmetric_key","DynamicReprovisioning":true,"AlwaysReprovisionOnStartup":false},"ServerVersion":"19.03.2","KernelVersion":"4.19.9","OperatingSystem":"ST OpenSTLinux - Weston - obr -(A Yocto Project Based Distro) 2.6-snapshot-20201111 (thud)","NumCpus":2,"Virtualized":"no"}, True

The "DynamicReprovisioning":true part came from iotedged, so that shows that dynamic_reprovisioning is set to true in config.yaml. What do the logs show if you set it to false?

pcurt commented 3 years ago

Yes I have tested dynamic_reprovisioning with both values.

In "Full syslog" this is the withdynamic_reprovisioning:true In the issue description there is the log with dynamic_reprovisioning:false

2020-11-17T14:49:51.883936+00:00 phycore-stm32mp1-peach iotedged[697]: 2020-11-17T14:49:51Z [INFO] - [mgmt] - - - [2020-11-17 14:49:51.881974065 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: <3> 2020-11-17 14:49:51.910 +00:00 [ERR] - Device client threw non-transient exception during setup
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]: Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: The specified SAS token is expired.)
2020-11-17T14:49:52+00:00 localhost edgeAgent[359]:  ---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: The specified SAS token is expired.

In both case we can see the log [2020-11-17 14:49:51.881974065 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-) that is the problem source.

damonbarry commented 3 years ago

In the case where dynamic_reprovisioning is false, it would be great to have the full iotedged and Edge agent logs. You can drag & drop the files into the comment window instead of having to copy/paste the whole thing...

pcurt commented 3 years ago

Here is the full log with dynamic_reprovisioning=false syslog.txt

damonbarry commented 3 years ago

@pcurt The syslog output you provided seems to truncate lines. For example, these lines are truncated, and missing text is replaced with ')':

2020-11-17T12:24:47.288845+00:00 phycore-stm32mp1-peach iotedged[711]: 2020-11-17T12:24:47Z [INFO] - [work] - - - [2020-11-17 12:24:47.286858983 UTC] "POST /modules/%24edgeAgent/genid/637350859244864312/)
2020-11-17T12:24:48.426082+00:00 phycore-stm32mp1-peach iotedged[711]: 2020-11-17T12:24:48Z [INFO] - [mgmt] - - - [2020-11-17 12:24:48.423979525 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP)

Can I get non-truncated logs for iotedged and Edge agent?

pcurt commented 3 years ago

Sorry for the truncated lines, Here is the full file not truncated. last_syslog_17-11-2020_21-24-24.log

damonbarry commented 3 years ago

I've spent quite a bit of time pouring over this log. Mostly, I'm trying to figure out the circumstances under which Edge agent would attempt to connect to the cloud with an expired SAS token (from the logs: Put token failed. status-code: 401, status-description: The specified SAS token is expired). If Edge agent is trying to connect for an hour or more and the token expires during that attempt, I could understand, but that's not the case here. It seems like iotedged starts up, and within 5 seconds Edge agent is running. 20 seconds later, Edge agent makes its first attempt to connect to the cloud--presumably with a fresh SAS token--which fails.

One possibility is clock skew. If there's a large disparity between your device's clock and IoT Hub's, then your device might be generating tokens that are, from the service's perspective, already expired. Can you confirm whether your device time is close to server time when this failure occurs? One option is to run iotedge check which tests for clock skew, among other things. Examine the output for any warnings or errors.

pcurt commented 3 years ago

I think your hypothesis is the explanation. Indeeded when our board is powered Off, the actual clock is backuped. We dont't have a RTC so when the board is powered On, two hours later, the clock is still set a date - 2 hours. When iotedge is started, when network is available, time is updated so there is a two hours gap between start time and current time.

Is there a way to modify or disable the SAS token management ?

FabGre commented 3 years ago

Hi @damonbarry We continue to make tests and think with @pcurt and it seems that the problem could be more tricky. Could you (or somebody on iot edge team) provide a sequence diagram to describ us the edgeAgent/iotedged DPS workflow and especially trigger-events involved ? Could you also share links to spot the relative source code on both edgeAgent and iotedged to help us understand ? (we tried to read the code but we didn't find all we want)

damonbarry commented 3 years ago

@pcurt I don't think there's a way to modify/disable SAS token management currently.

@massand Do you know if we have the documentation @FabGre is asking for above?

github-actions[bot] commented 3 years ago

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

massand commented 3 years ago

@FabGre - Generally the DPS provisioning occurs on iotedge startup (unless always_provision_on_startup is disabled - in which case it should skip provisioning if a backup file from previous successful device provisioning is present) OR when iotedged's /reprovision/ management API is invoked by edgeAgent (which occurs if edgeAgent cannot connect establish TLS connection with IoT Hub using the SaS token generated by iotedged using its provisioning data).

In code, you can start with the logic for provisioning in the BackupProvisioning struct (which wraps all types of provisioning) - https://github.com/Azure/iotedge/blob/master/edgelet/provisioning/src/provisioning.rs#L737 cc @arsing in case I missed anything

arsing commented 3 years ago

Provisioning isn't really relevant here. The problem happens because Edge Agent being tricked into using an expired SAS token. Its use of SAS tokens is non-optional because module identities only use symmetric key auth.

@FabGre Ensure iotedged is stopped before your device enters the low power state (which also ensures Edge Agent is stopped), and ensure the system time is fixed before starting iotedged (and thus Edge Agent) back up.

veyalla commented 3 years ago

@FabGre any updates on this?

FabGre commented 3 years ago

Hi @veyalla, for now we understood we're stuck with our clock problem. Waiting the hardware side for a RTU which help us to avoid the clock skew. I think you can close this issue. Thanks guys for your help.