EdgeAgent module is not able to authenticate during reprovisioning

[alaendle]

Expected Behavior

Reprovisioning should happen and bring device back to valid state.

Current Behavior

Endless reattempts of reprovisioning.

Steps to Reproduce

1. Delete and recreate IoTHub in the cloud

Context (Environment)

Output of iotedge check

I don't think this output is relaevant for this issue - I just added it for completeness. Please also note that the errors/wanings are all firewall related and do not indicate real problems. The really interessting logs are the ones of iotedged and the edgeAgent module included below.

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 - Error
    Unable to find image 'mcr.microsoft.com/azureiotedge-diagnostics:1.1.0' locally
    1.1.0: Pulling from azureiotedge-diagnostics
    801bfaa63ef2: Already exists
    5baca56f7803: Already exists
    342030e49d46: Already exists
    c8e13143a614: Pulling fs layer
    8623f9f8d167: Pulling fs layer
    c8e13143a614: Verifying Checksum
    c8e13143a614: Download complete
    8623f9f8d167: Verifying Checksum
    8623f9f8d167: Download complete
    c8e13143a614: Pull complete
    8623f9f8d167: Pull complete
    Digest: sha256:c37d16b515059c4065946fe7df77f6e6a3749e4cc21f0a2a8d13d67c17112990
    Status: Downloaded newer image for mcr.microsoft.com/azureiotedge-diagnostics:1.1.0
    One or more errors occurred. (Connection refused /var/lib/iotedge/mgmt.sock)
‼ latest security daemon - Warning
    Error while fetching latest versions of edge components: could not send HTTP request
‼ host time is close to real time - Warning
    Could not query NTP server
√ container time is close to host time - OK
√ DNS server - OK
√ production readiness: identity certificates expiry - OK
√ production readiness: certificates - OK
√ production readiness: container engine - OK
√ production readiness: logs policy - OK
√ production readiness: Edge Agent's storage directory is persisted on the host filesystem - 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 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 - Error
    Container on the default network could not connect to ioth-bhp-edge-qa.azure-devices.net:5671
× container on the default network can connect to IoT Hub HTTPS / WebSockets port - Error
    Container on the default network could not connect to ioth-bhp-edge-qa.azure-devices.net:443
× container on the default network can connect to IoT Hub MQTT port - Error
    Container on the default network could not connect to ioth-bhp-edge-qa.azure-devices.net:8883
× container on the IoT Edge module network can connect to IoT Hub AMQP port - Error
    Container on the azure-iot-edge network could not connect to ioth-bhp-edge-qa.azure-devices.net:5671
× container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - Error
    Container on the azure-iot-edge network could not connect to ioth-bhp-edge-qa.azure-devices.net:443
× container on the IoT Edge module network can connect to IoT Hub MQTT port - Error
    Container on the azure-iot-edge network could not connect to ioth-bhp-edge-qa.azure-devices.net:8883

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

Device Information

• Host OS: RHEL 7.9
• Architecture: x86_64
• Container OS: Linux containers

Runtime Versions

• aziot-edged 1.1.0
• Edge Agent 1.1.0
• Edge Hub 1.1.0
• Docker version 19.03.15+azure

Logs

aziot-edged logs

Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Finished provisioning edge device.
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Initializing the module runtime...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Initializing module runtime...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Successfully initialized module runtime
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Finished initializing the module runtime.
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping all modules...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module edgeHub...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [INFO] - Stopping module edgeAgent...
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module edgeHub
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:45:45 bh0vm00005 iotedged[120456]: 2021-02-22T10:45:45Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Finished stopping modules.
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - No change to configuration file detected.
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Starting management API...
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Starting workload API...
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Checking edge runtime status
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:46:15 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:15Z [INFO] - Starting module edgeAgent...
Feb 22 11:46:16 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:16Z [INFO] - Successfully started module edgeAgent
Feb 22 11:46:16 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:16Z [INFO] - [work] - - - [2021-02-22 10:46:16.674635140 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - Querying system info...
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: vmware
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - Successfully queried system info
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - [mgmt] - - - [2021-02-22 10:46:17.045697347 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - Querying system info...
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: vmware
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - Successfully queried system info
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - [mgmt] - - - [2021-02-22 10:46:17.515481556 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - [work] - - - [2021-02-22 10:46:17.629246461 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:46:17 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:17Z [INFO] - [mgmt] - - - [2021-02-22 10:46:17.809644205 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:46:18 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:18Z [INFO] - [work] - - - [2021-02-22 10:46:18.126355030 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:46:18 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:18Z [INFO] - [mgmt] - - - [2021-02-22 10:46:18.357407595 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:46:18 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:18Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:46:18 bh0vm00005 iotedged[120456]: 2021-02-22T10:46:18Z [ERR!] - The device has been de-provisioned
Feb 22 11:46:18 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:46:18 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:46:18 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:46:18 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:46:18 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:46:18 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Version - 1.1.0
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Configuring certificates...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Initializing hsm...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Finished initializing hsm.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Provisioning edge device...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Finished provisioning edge device.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Initializing the module runtime...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Initializing module runtime...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Successfully initialized module runtime
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Finished initializing the module runtime.
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping all modules...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module edgeHub...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [INFO] - Stopping module edgeAgent...
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module edgeHub
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:46:18 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:18Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Finished stopping modules.
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - No change to configuration file detected.
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Starting management API...
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Starting workload API...
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Checking edge runtime status
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:46:48 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:48Z [INFO] - Starting module edgeAgent...
Feb 22 11:46:49 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:49Z [INFO] - Successfully started module edgeAgent
Feb 22 11:46:49 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:49Z [INFO] - [work] - - - [2021-02-22 10:46:49.653114144 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - Querying system info...
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: vmware
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - Successfully queried system info
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - [mgmt] - - - [2021-02-22 10:46:50.033091063 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - Querying system info...
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: vmware
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - Successfully queried system info
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - [mgmt] - - - [2021-02-22 10:46:50.530842775 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - [work] - - - [2021-02-22 10:46:50.638026088 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:46:50 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:50Z [INFO] - [mgmt] - - - [2021-02-22 10:46:50.818896307 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:46:51 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:51Z [INFO] - [work] - - - [2021-02-22 10:46:51.153690842 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:46:51 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:51Z [INFO] - [mgmt] - - - [2021-02-22 10:46:51.402597993 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:46:51 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:51Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:46:51 bh0vm00005 iotedged[120710]: 2021-02-22T10:46:51Z [ERR!] - The device has been de-provisioned
Feb 22 11:46:51 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:46:51 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:46:51 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:46:51 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:46:51 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:46:51 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Version - 1.1.0
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Configuring certificates...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Initializing hsm...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Finished initializing hsm.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Provisioning edge device...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Finished provisioning edge device.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Initializing the module runtime...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Initializing module runtime...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Successfully initialized module runtime
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Finished initializing the module runtime.
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping all modules...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module edgeHub...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [INFO] - Stopping module edgeAgent...
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module edgeHub
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:46:51 bh0vm00005 iotedged[120982]: 2021-02-22T10:46:51Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Finished stopping modules.
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - No change to configuration file detected.
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Starting management API...
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Starting workload API...
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Checking edge runtime status
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:47:21 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:21Z [INFO] - Starting module edgeAgent...
Feb 22 11:47:22 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:22Z [INFO] - Successfully started module edgeAgent
Feb 22 11:47:22 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:22Z [INFO] - [work] - - - [2021-02-22 10:47:22.843362615 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - Querying system info...
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: vmware
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - Successfully queried system info
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - [mgmt] - - - [2021-02-22 10:47:23.220163577 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - Querying system info...
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: vmware
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - Successfully queried system info
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - [mgmt] - - - [2021-02-22 10:47:23.714285709 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:47:23 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:23Z [INFO] - [work] - - - [2021-02-22 10:47:23.856561884 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:47:24 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:24Z [INFO] - [mgmt] - - - [2021-02-22 10:47:24.043101616 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:47:24 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:24Z [INFO] - [work] - - - [2021-02-22 10:47:24.361877146 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:47:24 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:24Z [INFO] - [mgmt] - - - [2021-02-22 10:47:24.618103845 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:47:24 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:24Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:47:24 bh0vm00005 iotedged[120982]: 2021-02-22T10:47:24Z [ERR!] - The device has been de-provisioned
Feb 22 11:47:24 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:47:24 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:47:24 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:47:24 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:47:24 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:47:24 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Version - 1.1.0
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Configuring certificates...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Initializing hsm...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Finished initializing hsm.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Provisioning edge device...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Finished provisioning edge device.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Initializing the module runtime...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Initializing module runtime...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Successfully initialized module runtime
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Finished initializing the module runtime.
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping all modules...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module edgeHub...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [INFO] - Stopping module edgeAgent...
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module edgeHub
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:47:24 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:24Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Finished stopping modules.
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - No change to configuration file detected.
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Starting management API...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Starting workload API...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Checking edge runtime status
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Starting module edgeAgent...
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - Successfully started module edgeAgent
Feb 22 11:47:55 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:55Z [INFO] - [work] - - - [2021-02-22 10:47:55.960949646 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - Querying system info...
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: vmware
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - Successfully queried system info
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - [mgmt] - - - [2021-02-22 10:47:56.341048451 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - Querying system info...
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: vmware
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - Successfully queried system info
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - [mgmt] - - - [2021-02-22 10:47:56.830768864 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:47:56 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:56Z [INFO] - [work] - - - [2021-02-22 10:47:56.955203589 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:47:57 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:57Z [INFO] - [mgmt] - - - [2021-02-22 10:47:57.154465383 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:47:57 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:57Z [INFO] - [work] - - - [2021-02-22 10:47:57.516313351 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:47:57 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:57Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:47:57 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:57Z [INFO] - [mgmt] - - - [2021-02-22 10:47:57.773941009 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:47:57 bh0vm00005 iotedged[121236]: 2021-02-22T10:47:57Z [ERR!] - The device has been de-provisioned
Feb 22 11:47:57 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:47:57 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:47:57 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:47:57 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:47:57 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:47:57 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Version - 1.1.0
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Configuring certificates...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Initializing hsm...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Finished initializing hsm.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Provisioning edge device...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Finished provisioning edge device.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Initializing the module runtime...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Initializing module runtime...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Successfully initialized module runtime
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Finished initializing the module runtime.
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping all modules...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module edgeHub...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [INFO] - Stopping module edgeAgent...
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module edgeHub
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:47:58 bh0vm00005 iotedged[121497]: 2021-02-22T10:47:58Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Finished stopping modules.
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - No change to configuration file detected.
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Starting management API...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Starting workload API...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Checking edge runtime status
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Starting module edgeAgent...
Feb 22 11:48:28 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:28Z [INFO] - Successfully started module edgeAgent
Feb 22 11:48:29 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:29Z [INFO] - [work] - - - [2021-02-22 10:48:29.236274624 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:48:29 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:29Z [INFO] - Querying system info...
Feb 22 11:48:29 bh0vm00005 iotedged[121497]: vmware
Feb 22 11:48:29 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:29Z [INFO] - Successfully queried system info
Feb 22 11:48:29 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:29Z [INFO] - [mgmt] - - - [2021-02-22 10:48:29.632939320 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - Querying system info...
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: vmware
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - Successfully queried system info
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - [mgmt] - - - [2021-02-22 10:48:30.148991274 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - [work] - - - [2021-02-22 10:48:30.275334465 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - [mgmt] - - - [2021-02-22 10:48:30.472740579 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:48:30 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:30Z [INFO] - [work] - - - [2021-02-22 10:48:30.804898279 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:48:31 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:31Z [INFO] - [mgmt] - - - [2021-02-22 10:48:31.075296361 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:48:31 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:31Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:48:31 bh0vm00005 iotedged[121497]: 2021-02-22T10:48:31Z [ERR!] - The device has been de-provisioned
Feb 22 11:48:31 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:48:31 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:48:31 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:48:31 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:48:31 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:48:31 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Version - 1.1.0
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Configuring certificates...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Initializing hsm...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Finished initializing hsm.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Provisioning edge device...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Finished provisioning edge device.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Initializing the module runtime...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Initializing module runtime...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Successfully initialized module runtime
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Finished initializing the module runtime.
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping all modules...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module edgeHub...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [INFO] - Stopping module edgeAgent...
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module edgeHub
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:48:31 bh0vm00005 iotedged[121754]: 2021-02-22T10:48:31Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Finished stopping modules.
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - No change to configuration file detected.
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Starting management API...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Starting workload API...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Checking edge runtime status
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Starting module edgeAgent...
Feb 22 11:49:01 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:01Z [INFO] - Successfully started module edgeAgent
Feb 22 11:49:02 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:02Z [INFO] - [work] - - - [2021-02-22 10:49:02.455267486 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:49:02 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:02Z [INFO] - Querying system info...
Feb 22 11:49:02 bh0vm00005 iotedged[121754]: vmware
Feb 22 11:49:02 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:02Z [INFO] - Successfully queried system info
Feb 22 11:49:02 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:02Z [INFO] - [mgmt] - - - [2021-02-22 10:49:02.830112001 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - Querying system info...
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: vmware
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - Successfully queried system info
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - [mgmt] - - - [2021-02-22 10:49:03.309843594 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - [work] - - - [2021-02-22 10:49:03.426505367 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - [mgmt] - - - [2021-02-22 10:49:03.619239016 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:49:03 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:03Z [INFO] - [work] - - - [2021-02-22 10:49:03.895104427 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:49:04 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:04Z [INFO] - [mgmt] - - - [2021-02-22 10:49:04.151216173 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:49:04 bh0vm00005 iotedged[121754]: 2021-02-22T10:49:04Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:49:04 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:49:04 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:49:04 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:49:04 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:49:04 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:49:04 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Version - 1.1.0
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Configuring certificates...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Initializing hsm...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Finished initializing hsm.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Provisioning edge device...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Finished provisioning edge device.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Initializing the module runtime...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Initializing module runtime...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Successfully initialized module runtime
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Finished initializing the module runtime.
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping all modules...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module edgeHub...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [INFO] - Stopping module edgeAgent...
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module edgeHub
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:49:04 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:04Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Finished stopping modules.
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - No change to configuration file detected.
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Starting management API...
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Starting workload API...
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Checking edge runtime status
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:49:34 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:34Z [INFO] - Starting module edgeAgent...
Feb 22 11:49:35 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:35Z [INFO] - Successfully started module edgeAgent
Feb 22 11:49:35 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:35Z [INFO] - [work] - - - [2021-02-22 10:49:35.726663914 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - Querying system info...
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: vmware
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - Successfully queried system info
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - [mgmt] - - - [2021-02-22 10:49:36.125972680 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - Querying system info...
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: vmware
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - Successfully queried system info
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - [mgmt] - - - [2021-02-22 10:49:36.618225436 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - [work] - - - [2021-02-22 10:49:36.733323557 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:49:36 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:36Z [INFO] - [mgmt] - - - [2021-02-22 10:49:36.928194379 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:49:37 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:37Z [INFO] - [work] - - - [2021-02-22 10:49:37.228317586 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:49:37 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:37Z [INFO] - [mgmt] - - - [2021-02-22 10:49:37.483256986 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:49:37 bh0vm00005 iotedged[123216]: 2021-02-22T10:49:37Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:49:37 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:49:37 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:49:37 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:49:37 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:49:37 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:49:37 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Version - 1.1.0
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Configuring certificates...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Initializing hsm...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Finished initializing hsm.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Provisioning edge device...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Finished provisioning edge device.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Initializing the module runtime...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Initializing module runtime...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Successfully initialized module runtime
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Finished initializing the module runtime.
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping all modules...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module edgeHub...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [INFO] - Stopping module edgeAgent...
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module edgeHub
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:49:37 bh0vm00005 iotedged[123473]: 2021-02-22T10:49:37Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Finished stopping modules.
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - No change to configuration file detected.
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Starting management API...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Starting workload API...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Checking edge runtime status
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Starting module edgeAgent...
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - Successfully started module edgeAgent
Feb 22 11:50:08 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:08Z [INFO] - [work] - - - [2021-02-22 10:50:08.968387346 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - Querying system info...
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: vmware
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - Successfully queried system info
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - [mgmt] - - - [2021-02-22 10:50:09.373284725 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - Querying system info...
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: vmware
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - Successfully queried system info
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - [mgmt] - - - [2021-02-22 10:50:09.880671239 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:50:09 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:09Z [INFO] - [work] - - - [2021-02-22 10:50:09.996460380 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:50:10 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:10Z [INFO] - [mgmt] - - - [2021-02-22 10:50:10.179627113 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:50:10 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:10Z [INFO] - [work] - - - [2021-02-22 10:50:10.516141635 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:50:10 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:10Z [INFO] - [mgmt] - - - [2021-02-22 10:50:10.763032955 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:50:10 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:10Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:50:10 bh0vm00005 iotedged[123473]: 2021-02-22T10:50:10Z [ERR!] - The device has been de-provisioned
Feb 22 11:50:10 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:50:10 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:50:10 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:50:10 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:50:10 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:50:11 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Version - 1.1.0
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Configuring certificates...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Initializing hsm...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Finished initializing hsm.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Provisioning edge device...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Finished provisioning edge device.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Initializing the module runtime...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Initializing module runtime...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Successfully initialized module runtime
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Finished initializing the module runtime.
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping all modules...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module edgeHub...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [INFO] - Stopping module edgeAgent...
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module edgeHub
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:50:11 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:11Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Finished stopping modules.
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - No change to configuration file detected.
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Starting management API...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Starting workload API...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Checking edge runtime status
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Starting module edgeAgent...
Feb 22 11:50:41 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:41Z [INFO] - Successfully started module edgeAgent
Feb 22 11:50:42 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:42Z [INFO] - [work] - - - [2021-02-22 10:50:42.240655746 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:50:42 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:42Z [INFO] - Querying system info...
Feb 22 11:50:42 bh0vm00005 iotedged[123851]: vmware
Feb 22 11:50:42 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:42Z [INFO] - Successfully queried system info
Feb 22 11:50:42 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:42Z [INFO] - [mgmt] - - - [2021-02-22 10:50:42.614885991 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - Querying system info...
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: vmware
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - Successfully queried system info
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - [mgmt] - - - [2021-02-22 10:50:43.095592975 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - [work] - - - [2021-02-22 10:50:43.208435227 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - [mgmt] - - - [2021-02-22 10:50:43.402072831 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - [work] - - - [2021-02-22 10:50:43.699576688 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - [mgmt] - - - [2021-02-22 10:50:43.960106398 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:50:43 bh0vm00005 iotedged[123851]: 2021-02-22T10:50:43Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:50:43 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:50:43 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:50:43 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:50:44 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:50:44 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:50:44 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Version - 1.1.0
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Configuring certificates...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Initializing hsm...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Finished initializing hsm.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Provisioning edge device...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Finished provisioning edge device.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Initializing the module runtime...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Initializing module runtime...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Successfully initialized module runtime
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Finished initializing the module runtime.
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping all modules...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module edgeHub...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [INFO] - Stopping module edgeAgent...
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module edgeHub
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:50:44 bh0vm00005 iotedged[124227]: 2021-02-22T10:50:44Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Finished stopping modules.
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - No change to configuration file detected.
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Starting management API...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Starting workload API...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Checking edge runtime status
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Starting module edgeAgent...
Feb 22 11:51:14 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:14Z [INFO] - Successfully started module edgeAgent
Feb 22 11:51:15 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:15Z [INFO] - [work] - - - [2021-02-22 10:51:15.416014659 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:51:15 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:15Z [INFO] - Querying system info...
Feb 22 11:51:15 bh0vm00005 iotedged[124227]: vmware
Feb 22 11:51:15 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:15Z [INFO] - Successfully queried system info
Feb 22 11:51:15 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:15Z [INFO] - [mgmt] - - - [2021-02-22 10:51:15.810360229 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - Querying system info...
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: vmware
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - Successfully queried system info
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - [mgmt] - - - [2021-02-22 10:51:16.296301141 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - [work] - - - [2021-02-22 10:51:16.404114515 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - [mgmt] - - - [2021-02-22 10:51:16.598362253 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:51:16 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:16Z [INFO] - [work] - - - [2021-02-22 10:51:16.935708155 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:51:17 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:17Z [INFO] - [mgmt] - - - [2021-02-22 10:51:17.211283703 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:51:17 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:17Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:51:17 bh0vm00005 iotedged[124227]: 2021-02-22T10:51:17Z [ERR!] - The device has been de-provisioned
Feb 22 11:51:17 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:51:17 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:51:17 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:51:17 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:51:17 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:51:17 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Version - 1.1.0
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Configuring certificates...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Initializing hsm...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Finished initializing hsm.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Provisioning edge device...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Finished provisioning edge device.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Initializing the module runtime...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Initializing module runtime...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Successfully initialized module runtime
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Finished initializing the module runtime.
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping all modules...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module edgeHub...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [INFO] - Stopping module edgeAgent...
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module edgeHub
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:51:17 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:17Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Successfully stopped module edgeAgent
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Finished stopping modules.
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Detecting if configuration file has changed...
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - No change to configuration file detected.
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Edge issuer CA expiration date: 2036-02-06T16:48:02Z
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Obtaining workload CA succeeded.
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Starting management API...
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Starting workload API...
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Starting watchdog with 60 second frequency...
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Listening on unix:///var/lib/iotedge/mgmt.sock with 1 thread for management API.
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Listening on unix:///var/lib/iotedge/workload.sock with 1 thread for workload API.
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Checking edge runtime status
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Edge runtime status is failed, starting module now...
Feb 22 11:51:47 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:47Z [INFO] - Starting module edgeAgent...
Feb 22 11:51:48 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:48Z [INFO] - Successfully started module edgeAgent
Feb 22 11:51:48 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:48Z [INFO] - [work] - - - [2021-02-22 10:51:48.708440177 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1994 "-" "-" auth_id(-)
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - Querying system info...
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: vmware
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - Successfully queried system info
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - [mgmt] - - - [2021-02-22 10:51:49.092892570 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - Querying system info...
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: vmware
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - Successfully queried system info
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - [mgmt] - - - [2021-02-22 10:51:49.598905702 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 317 "-" "-" auth_id(-)
Feb 22 11:51:49 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:49Z [INFO] - [work] - - - [2021-02-22 10:51:49.883097015 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 6068 "-" "-" auth_id(-)
Feb 22 11:51:50 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:50Z [INFO] - [mgmt] - - - [2021-02-22 10:51:50.072664431 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5839 "-" "-" auth_id(-)
Feb 22 11:51:50 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:50Z [INFO] - [work] - - - [2021-02-22 10:51:50.241131931 UTC] "POST /modules/%24edgeAgent/genid/637485497193754825/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Feb 22 11:51:50 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:50Z [INFO] - [mgmt] - - - [2021-02-22 10:51:50.477072697 UTC] "POST /device/reprovision?api-version=2020-07-07 HTTP/1.1" 200 OK - "-" "-" auth_id(-)
Feb 22 11:51:50 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:50Z [INFO] - Edge runtime will stop because of the device reprovisioning signal.
Feb 22 11:51:50 bh0vm00005 iotedged[124566]: 2021-02-22T10:51:50Z [ERR!] - The device has been de-provisioned
Feb 22 11:51:50 bh0vm00005 systemd[1]: iotedge.service: main process exited, code=exited, status=154/n/a
Feb 22 11:51:50 bh0vm00005 systemd[1]: Unit iotedge.service entered failed state.
Feb 22 11:51:50 bh0vm00005 systemd[1]: iotedge.service failed.
Feb 22 11:51:50 bh0vm00005 systemd[1]: iotedge.service holdoff time over, scheduling restart.
Feb 22 11:51:50 bh0vm00005 systemd[1]: Stopped Azure IoT Edge daemon.
Feb 22 11:51:50 bh0vm00005 systemd[1]: Started Azure IoT Edge daemon.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Starting Azure IoT Edge Security Daemon
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Version - 1.1.0
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Using config file: /etc/iotedge/config.yaml
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Configuring /var/lib/iotedge as the home directory.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Configuring certificates...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Configuring the Device CA certificate using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA-full-chain.cert.pem".
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Configuring the Device private key using "/etc/iotedge/iot-edge-device-ca-bh0vm00005CA.key.pem".
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Configuring the trusted CA certificates using "/etc/iotedge/azure-iot.root.ca.cert.pem".
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Finished configuring provisioning environment variables and certificates.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Initializing hsm...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Finished initializing hsm.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Initializing hsm X509 interface...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Detected HTTPS proxy server http://rb-proxy-sl.bosch.com:8080/
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Finished initializing hsm X509 interface...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Provisioning edge device...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Starting provisioning edge device via manual mode using X509 identity certificate...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Manually provisioning device "bh0vm00005" in hub "ioth-bhp-edge-qa.azure-devices.net"
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Finished provisioning edge device.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Initializing the module runtime...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Initializing module runtime...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Using runtime network id azure-iot-edge
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Successfully initialized module runtime
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Finished initializing the module runtime.
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping all modules...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module spex-bridge-solace...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module baseline-metrics...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module curve-grabber-metrics...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module edgeHub...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module spex-bridge-redis...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module spex-bridge-metrics...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module spex-bridge-rabbitmq...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module curve-grabber-watcher...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module curve-grabber-solace...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [INFO] - Stopping module edgeAgent...
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module spex-bridge-solace
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module baseline-metrics
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module curve-grabber-metrics
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module edgeHub
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module spex-bridge-redis
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module spex-bridge-metrics
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module curve-grabber-watcher
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module spex-bridge-rabbitmq
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] - Could not stop module curve-grabber-solace
Feb 22 11:51:50 bh0vm00005 iotedged[124823]: 2021-02-22T10:51:50Z [WARN] -         caused by: Target of operation already in this state

edge-agent logs

2021-02-22 10:52:54  Starting Edge Agent
2021-02-22 10:52:54  Changing ownership of storage folder: /storage/edgeAgent to 1000
2021-02-22 10:52:54  Changing ownership of management socket: /var/lib/iotedge/mgmt.sock
2021-02-22 10:52:55.021 +00:00 Edge Agent Main()
<6> 2021-02-22 10:52:55.184 +00:00 [INF] - Initializing Edge Agent.
<6> 2021-02-22 10:52:55.350 +00:00 [INF] - Version - 1.1.0.39334128 (92ac4878a4c8ca74c0db14cd2e63273f1c8661f4)
<6> 2021-02-22 10:52:55.350 +00:00 [INF] -
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

 ██╗ ██████╗ ████████╗    ███████╗██████╗  ██████╗ ███████╗
 ██║██╔═══██╗╚══██╔══╝    ██╔════╝██╔══██╗██╔════╝ ██╔════╝
 ██║██║   ██║   ██║       █████╗  ██║  ██║██║  ███╗█████╗
 ██║██║   ██║   ██║       ██╔══╝  ██║  ██║██║   ██║██╔══╝
 ██║╚██████╔╝   ██║       ███████╗██████╔╝╚██████╔╝███████╗
 ╚═╝ ╚═════╝    ╚═╝       ╚══════╝╚═════╝  ╚═════╝ ╚══════╝

<6> 2021-02-22 10:52:55.366 +00:00 [INF] - Detected proxy http://rb-proxy-sl.bosch.com:8080/
<6> 2021-02-22 10:52:55.397 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2021-02-22 10:52:55.522 +00:00 [INF] - Installing certificates [CN=Azure_IoT_Hub_CA_Cert:02/06/2036 16:47:37] to Root
<6> 2021-02-22 10:52:55.653 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics
<6> 2021-02-22 10:52:55.802 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2021-02-22 10:52:55.806 +00:00 [INF] - Started operation Get system resources
<6> 2021-02-22 10:52:55.808 +00:00 [INF] - Collecting metadata metrics
<6> 2021-02-22 10:52:55.875 +00:00 [INF] - Set metadata metrics: 1.1.0.39334128 (92ac4878a4c8ca74c0db14cd2e63273f1c8661f4), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"x86_64","Version":"1.1.0","Provisioning":{"Type":"manual.x509","DynamicReprovisioning":true},"ServerVersion":"19.03.15+azure","KernelVersion":"3.10.0-1160.15.2.el7.x86_64","OperatingSystem":"Red Hat Enterprise Linux","NumCpus":4,"Virtualized":"yes"}, True
<6> 2021-02-22 10:52:56.307 +00:00 [INF] - Created persistent store at /storage/edgeAgent
<6> 2021-02-22 10:52:56.328 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2021-02-22 10:52:56.332 +00:00 [INF] - Started operation refresh twin config
<6> 2021-02-22 10:52:56.351 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<6> 2021-02-22 10:52:56.384 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2021-02-22 10:52:56.385 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2021-02-22 10:52:56.385 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2021-02-22 10:52:56.385 +00:00 [INF] - Registering request handler RestartModule
<3> 2021-02-22 10:52:57.325 +00:00 [ERR] - Device client threw non-transient exception during setup
Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: Unauthorized: Device 'bh0vm00005/$edgeAgent' at IotHub 'ioth-bhp-edge-qa' does not have PrimaryKey or SecondaryKey.)
 ---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: Unauthorized: Device 'bh0vm00005/$edgeAgent' at IotHub 'ioth-bhp-edge-qa' does not have PrimaryKey or SecondaryKey.
   at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AsyncResult`1.End(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.AmqpCbsLink.EndSendToken(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)
   --- End of inner exception stack trace ---
   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 219
   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 170
--- End of stack trace from previous location where exception was thrown ---
   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 152
<6> 2021-02-22 10:52:57.343 +00:00 [INF] - Termination requested, initiating shutdown.
<6> 2021-02-22 10:52:57.343 +00:00 [INF] - Waiting for cleanup to finish
<4> 2021-02-22 10:53:01.667 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/storage/edgeAgent/backup.json) instead
<3> 2021-02-22 10:53:01.679 +00:00 [ERR] - Shutting down because no response from unix:///var/lib/iotedge/workload.sock for Decrypt
System.Net.Internals.SocketExceptionFactory+ExtendedSocketException (111): Connection refused /var/lib/iotedge/workload.sock
   at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
   at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
   at System.Net.Sockets.Socket.UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state, Boolean flowContext)
   at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
   at System.Net.Sockets.Socket.ConnectAsync(EndPoint remoteEP)
   at System.Net.Sockets.SocketTaskExtensions.ConnectAsync(Socket socket, EndPoint remoteEP)
   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.GetConnectedSocketAsync() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 47
   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 23
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2018_06_28.GeneratedCode.HttpWorkloadClient.DecryptAsync(String api_version, String name, String genid, DecryptRequest payload, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2018_06_28/generatedCode/HttpWorkloadClient.cs:line 353
   at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 126
   at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 59
2021-02-22 10:53:28  Starting Edge Agent
2021-02-22 10:53:28  Changing ownership of storage folder: /storage/edgeAgent to 1000
2021-02-22 10:53:28  Changing ownership of management socket: /var/lib/iotedge/mgmt.sock
2021-02-22 10:53:28.293 +00:00 Edge Agent Main()
<6> 2021-02-22 10:53:28.462 +00:00 [INF] - Initializing Edge Agent.
<6> 2021-02-22 10:53:28.617 +00:00 [INF] - Version - 1.1.0.39334128 (92ac4878a4c8ca74c0db14cd2e63273f1c8661f4)
<6> 2021-02-22 10:53:28.618 +00:00 [INF] -
        █████╗ ███████╗██╗   ██╗██████╗ ███████╗
       ██╔══██╗╚══███╔╝██║   ██║██╔══██╗██╔════╝
       ███████║  ███╔╝ ██║   ██║██████╔╝█████╗
       ██╔══██║ ███╔╝  ██║   ██║██╔══██╗██╔══╝
       ██║  ██║███████╗╚██████╔╝██║  ██║███████╗
       ╚═╝  ╚═╝╚══════╝ ╚═════╝ ╚═╝  ╚═╝╚══════╝

 ██╗ ██████╗ ████████╗    ███████╗██████╗  ██████╗ ███████╗
 ██║██╔═══██╗╚══██╔══╝    ██╔════╝██╔══██╗██╔════╝ ██╔════╝
 ██║██║   ██║   ██║       █████╗  ██║  ██║██║  ███╗█████╗
 ██║██║   ██║   ██║       ██╔══╝  ██║  ██║██║   ██║██╔══╝
 ██║╚██████╔╝   ██║       ███████╗██████╔╝╚██████╔╝███████╗
 ╚═╝ ╚═════╝    ╚═╝       ╚══════╝╚═════╝  ╚═════╝ ╚══════╝

<6> 2021-02-22 10:53:28.633 +00:00 [INF] - Detected proxy http://rb-proxy-sl.bosch.com:8080/
<6> 2021-02-22 10:53:28.663 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2021-02-22 10:53:28.790 +00:00 [INF] - Installing certificates [CN=Azure_IoT_Hub_CA_Cert:02/06/2036 16:47:37] to Root
<6> 2021-02-22 10:53:28.932 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics
<6> 2021-02-22 10:53:29.091 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2021-02-22 10:53:29.096 +00:00 [INF] - Started operation Get system resources
<6> 2021-02-22 10:53:29.098 +00:00 [INF] - Collecting metadata metrics
<6> 2021-02-22 10:53:29.168 +00:00 [INF] - Set metadata metrics: 1.1.0.39334128 (92ac4878a4c8ca74c0db14cd2e63273f1c8661f4), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"x86_64","Version":"1.1.0","Provisioning":{"Type":"manual.x509","DynamicReprovisioning":true},"ServerVersion":"19.03.15+azure","KernelVersion":"3.10.0-1160.15.2.el7.x86_64","OperatingSystem":"Red Hat Enterprise Linux","NumCpus":4,"Virtualized":"yes"}, True
<6> 2021-02-22 10:53:29.619 +00:00 [INF] - Created persistent store at /storage/edgeAgent
<6> 2021-02-22 10:53:29.646 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2021-02-22 10:53:29.650 +00:00 [INF] - Started operation refresh twin config
<6> 2021-02-22 10:53:29.670 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<6> 2021-02-22 10:53:29.711 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2021-02-22 10:53:29.711 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2021-02-22 10:53:29.711 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2021-02-22 10:53:29.711 +00:00 [INF] - Registering request handler RestartModule
<3> 2021-02-22 10:53:30.709 +00:00 [ERR] - Device client threw non-transient exception during setup
Microsoft.Azure.Devices.Client.Exceptions.UnauthorizedException: error(condition:amqp:unauthorized-access,description:Put token failed. status-code: 401, status-description: Unauthorized: Device 'bh0vm00005/$edgeAgent' at IotHub 'ioth-bhp-edge-qa' does not have PrimaryKey or SecondaryKey.)
 ---> Microsoft.Azure.Amqp.AmqpException: Put token failed. status-code: 401, status-description: Unauthorized: Device 'bh0vm00005/$edgeAgent' at IotHub 'ioth-bhp-edge-qa' does not have PrimaryKey or SecondaryKey.
   at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AsyncResult`1.End(IAsyncResult asyncResult)
   at Microsoft.Azure.Amqp.AmqpCbsLink.EndSendToken(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)
   --- End of inner exception stack trace ---
   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 219
   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 170
--- End of stack trace from previous location where exception was thrown ---
   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 152
<6> 2021-02-22 10:53:30.730 +00:00 [INF] - Termination requested, initiating shutdown.
<6> 2021-02-22 10:53:30.730 +00:00 [INF] - Waiting for cleanup to finish
<4> 2021-02-22 10:53:34.987 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/storage/edgeAgent/backup.json) instead
<3> 2021-02-22 10:53:35.001 +00:00 [ERR] - Shutting down because no response from unix:///var/lib/iotedge/workload.sock for Decrypt
System.Net.Internals.SocketExceptionFactory+ExtendedSocketException (111): Connection refused /var/lib/iotedge/workload.sock
   at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
   at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
   at System.Net.Sockets.Socket.UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state, Boolean flowContext)
   at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
   at System.Net.Sockets.Socket.ConnectAsync(EndPoint remoteEP)
   at System.Net.Sockets.SocketTaskExtensions.ConnectAsync(Socket socket, EndPoint remoteEP)
   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.GetConnectedSocketAsync() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 47
   at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 23
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2018_06_28.GeneratedCode.HttpWorkloadClient.DecryptAsync(String api_version, String name, String genid, DecryptRequest payload, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2018_06_28/generatedCode/HttpWorkloadClient.cs:line 353
   at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 126
   at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 59

Additional Information

docker ps returns

CONTAINER ID   IMAGE                                        COMMAND                  CREATED      STATUS          PORTS                    NAMES
3c05470c77f6   mcr.microsoft.com/azureiotedge-agent:1.1.0   "/bin/sh -c 'exec /a…"   5 days ago   Up 17 seconds   0.0.0.0:8082->9600/tcp   edgeAgent

So it caught my attention that the command shows that the container was created 5 days ago, while it restarts every few seconds; so my assumption is that the state of the container is just wrong/not updated. However I have dynamic_reprovisioning set to true and no clock skew. Could it matter the timezones of host (CET) and container (UTC) are not identical (but personally I don't believe that makes a difference)?

So this issue is related but not identical to #4241 and #3982. Please let me know if I was unclear or if I could contribute further information.

[pmzara]

@alaendle Thanks for reporting this issue. We're investigating.

[arsing]

iotedge/edgelet/edgelet-core/src/watchdog.rs

Lines 179 to 197 in e4c6eae

	Some(state) => {
	let res = if *state.status() == ModuleStatus::Running {
	info!("Edge runtime is running.");
	future::Either::A(future::ok(()))
	} else {
	info!(
	"Edge runtime status is {}, starting module now...",
	*state.status(),
	);
	future::Either::B(
	runtime
	.start(&module)
	.map_err(|e| Error::from(e.context(ErrorKind::ModuleRuntime))),
	)
	};
	Either::A(res)
	}
	None => Either::B(create_and_start(runtime, &id_mgr, spec, module_id)),

It's a bug. We only recreate the EA module identity in Hub if the EA container doesn't already exist.

You can work around it with docker rm -f edgeAgent, but of course the point of dynamic_reprovisioning: true is to not require manual intervention.

[github-actions]

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

[gordonwang0]

#4833 should resolve this. Closing issue.