iotedge: Iot Hub occasionally throws TLS errors and modules cannot connect
Expected Behavior
The iot hub should always start up successfully and handle connections
Current Behavior
The iot hub logs the following exception after startup and my module fails to connect. After running iotedge restart edgeHub the issue is resolved, but it happens again occasionally after restarting iotedge.
Steps to Reproduce
Provide a detailed set of steps to reproduce the bug.
- Deploy and initialize an edge device with multiple modules using the steps here https://docs.microsoft.com/en-us/azure/iot-edge/quickstart?view=iotedge-2018-06
- Around 30% of the time, the modules will fail to start up because they fail to connect to the iot hub.
The IoT Hub is logging this error
<3> 2021-06-07 19:29:40.066 +00:00 [ERR] - Unhandled exception while processing "0HM99T3N38MRQ".
System.ComponentModel.Win32Exception (0x8009030D): The credentials supplied to the package were not recognized
Context (Environment)
Output of iotedge check
Click here
Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ Windows host version is supported - OK
√ config.yaml has correct hostname - OK
√ config.yaml has correct URIs for daemon mgmt endpoint - OK
√ latest security daemon - OK
√ host time is close to real time - OK
√ container time is close to host time - OK
‼ DNS server - Warning
Container engine is not configured with DNS server setting, which may impact connectivity to IoT Hub.
Please see https://aka.ms/iotedge-prod-checklist-dns for best practices.
You can ignore this warning if you are setting DNS server per module in the Edge deployment.
‼ production readiness: certificates - Warning
The Edge device is using self-signed automatically-generated development certificates.
They will expire in 89 days (at 2021-09-05 19:11:43 UTC) causing module-to-module and downstream device communication to fail on an active deployment.
After the certs have expired, restarting the IoT Edge daemon will trigger it to generate new development certs.
Please consider using production certificates instead. See https://aka.ms/iotedge-prod-checklist-certs for best practices.
√ production readiness: container engine - OK
‼ production readiness: logs policy - Warning
Container engine is not configured to rotate module logs which may cause it run out of disk space.
Please see https://aka.ms/iotedge-prod-checklist-logs for best practices.
You can ignore this warning if you are setting log policy per module in the Edge deployment.
‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning
The edgeAgent module is not configured to persist its C:\Windows\Temp\edgeAgent directory on the host filesystem.
Data might be lost if the module is deleted or updated.
Please see https://aka.ms/iotedge-storage-host for best practices.
‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning
The edgeHub module is not configured to persist its C:\Windows\Temp\edgeHub directory on the host filesystem.
Data might be lost if the module is deleted or updated.
Please see https://aka.ms/iotedge-storage-host for best practices.
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 IoT Edge module network can connect to IoT Hub AMQP port - OK
√ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK
16 check(s) succeeded.
5 check(s) raised warnings. Re-run with --verbose for more details.
Device Information
- Host OS: Windows (Windows Server 2019 Datacenter) 10.0.17763
- Architecture: x86_64:
- Container OS: Windows Containers
Runtime Versions
- aziot-edged: iotedge 1.1.3 (68e71a5384b14956775241557877497274d0ce7e)
- Edge Agent: mcr.microsoft.com/azureiotedge-agent:1.0
- Edge Hub: mcr.microsoft.com/azureiotedge-hub:1.0
- Docker/Moby [run
docker version]: 19.03.12+azure
Note: when using Windows containers on Windows, run docker -H npipe:////./pipe/iotedge_moby_engine version instead
Logs
aziot-edged logs
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged::app -- Version - 1.1.3 (68e71a5384b14956775241557877497274d0ce7e)
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged::app -- Using config file: C:\ProgramData\iotedge\config.yaml
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged::windows -- Initializing iotedged service.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged::app -- Starting Azure IoT Edge Security Daemon
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged::windows -- Starting iotedged service.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Finished configuring provisioning environment variables and certificates.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Initializing hsm...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\hsm_log.c:log_init:41) Initialized logging
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Configuring C:\ProgramData\iotedge as the home directory.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Configuring certificates...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Transparent gateway certificates not found, operating in quick start mode...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:generate_edge_hsm_certificates_if_needed:1629) Load status 1. Regenerating owner and device CA certs and keys
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
TimeCreated : 6/7/2021 7:11:43 PM
Message : error: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\hsm_utils.c:create_file_handle_for_reading:59) Could not open file for reading
C:\ProgramData\iotedge\hsm\enc_keys\edgelet-masterWt5mT2xpO72EPKlt2Tt0Sq4uJCrMvfl2rzzKRB3pnyo_.enc.key. GetLastError=00000002
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:load_encryption_key_from_file:818) Could not read encryption key from file. No key file exists or is invalid or permission error.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Provisioning edge device...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Finished initializing hsm.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Starting provisioning edge device via manual mode using a device connection string...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: provisioning::provisioning -- Manually provisioning device "946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7" in hub "edgeiothubqa.azure-devices.net"
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: edgelet_docker::runtime -- Initializing module runtime...
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: edgelet_docker::runtime -- Using runtime network id nat
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Finished provisioning edge device.
TimeCreated : 6/7/2021 7:11:43 PM
Message : info: iotedged -- Initializing the module runtime...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Stopping all modules...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Finished initializing the module runtime.
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: edgelet_docker::runtime -- Successfully initialized module runtime
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Change to configuration file detected.
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Removing all modules...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Finished stopping modules.
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Detecting if configuration file has changed...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: iotedged-workload-ca
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Edge issuer CA expiration date: 2021-09-05T19:11:43Z
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Finished removing modules.
TimeCreated : 6/7/2021 7:11:45 PM
Message : error: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:remove_if_cert_and_key_exist_by_alias:1443) Certificate and key file for alias do not exist iotedged-workload-ca
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 4096
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedged-workload-ca
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias iotedge-tls
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Starting management API...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: edgelet_core::watchdog -- Starting watchdog with 60 second frequency...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Starting workload API...
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Listening on unix:///C:/ProgramData/iotedge/mgmt/sock with 1 thread for management API.
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: iotedged -- Listening on unix:///C:/ProgramData/iotedge/workload/sock with 1 thread for workload API.
TimeCreated : 6/7/2021 7:11:45 PM
Message : info: edgelet_core::watchdog -- Creating and starting edge runtime module edgeAgent
TimeCreated : 6/7/2021 7:11:46 PM
Message : info: edgelet_core::watchdog -- Updating identity for module $edgeAgent
TimeCreated : 6/7/2021 7:11:46 PM
Message : info: edgelet_docker::runtime -- Pulling image mcr.microsoft.com/azureiotedge-agent:1.1...
TimeCreated : 6/7/2021 7:12:14 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:14.303277800 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 14 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:12:34 PM
Message : info: edgelet_docker::runtime -- Creating module edgeAgent...
TimeCreated : 6/7/2021 7:12:34 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.1
TimeCreated : 6/7/2021 7:12:34 PM
Message : info: edgelet_docker::runtime -- Starting module edgeAgent...
TimeCreated : 6/7/2021 7:12:34 PM
Message : info: edgelet_docker::runtime -- Successfully created module edgeAgent
TimeCreated : 6/7/2021 7:12:36 PM
Message : info: edgelet_docker::runtime -- Successfully started module edgeAgent
TimeCreated : 6/7/2021 7:12:37 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:12:37.998174200 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:38 PM
Message : info: edgelet_docker::runtime -- Querying system info...
TimeCreated : 6/7/2021 7:12:38 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:38.740383600 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 454 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:38 PM
Message : info: edgelet_docker::runtime -- Successfully queried system info
TimeCreated : 6/7/2021 7:12:39 PM
Message : info: edgelet_docker::runtime -- Querying system info...
TimeCreated : 6/7/2021 7:12:39 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:39.743372300 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 454 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:39 PM
Message : info: edgelet_docker::runtime -- Successfully queried system info
TimeCreated : 6/7/2021 7:12:39 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:39.857301 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:40 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:12:40.176083900 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:41 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:12:41.574202600 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5385 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:41 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:41.764624700 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 771 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:41 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:41.955145600 UTC] "PUT /identities/spectrum-pageservice?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:42.111483300 UTC] "PUT /identities/spectrum-cloudstoreservice?api-version=2020-07-07 HTTP/1.1" 200 OK 116 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:42.266484700 UTC] "PUT /identities/spectrum-logservice?api-version=2020-07-07 HTTP/1.1" 200 OK 109 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:42.556821100 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:42.567821200 UTC] "PUT /identities/spectrum-claimsservice?api-version=2020-07-07 HTTP/1.1" 200 OK 112 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:12:42.575823300 UTC] "PUT /identities/spectrum-syncservice?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:12:42 PM
Message : info: edgelet_docker::runtime -- Pulling image mcr.microsoft.com/azureiotedge-agent:1.0...
TimeCreated : 6/7/2021 7:12:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:12:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:13:34 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:34.387074500 UTC] "POST /modules/edgeAgent/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:34 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0
TimeCreated : 6/7/2021 7:13:34 PM
Message : info: edgelet_docker::runtime -- Removing module edgeAgent...
TimeCreated : 6/7/2021 7:13:34 PM
Message : info: edgelet_http_mgmt::server::module::update -- Updating and starting module edgeAgent
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Pulling image mcr.microsoft.com/azureiotedge-agent:1.0...
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Successfully removed module edgeAgent
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Creating module edgeAgent...
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image mcr.microsoft.com/azureiotedge-agent:1.0
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Starting module edgeAgent...
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_http_mgmt::server::module::update -- Starting module edgeAgent
TimeCreated : 6/7/2021 7:13:35 PM
Message : info: edgelet_docker::runtime -- Successfully created module edgeAgent
TimeCreated : 6/7/2021 7:13:37 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:37.009848500 UTC] "PUT /modules/edgeAgent?api-version=2020-07-07&start=true HTTP/1.1" 200 OK 1356 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:37 PM
Message : info: edgelet_docker::runtime -- Successfully started module edgeAgent
TimeCreated : 6/7/2021 7:13:38 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:13:38.807814400 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:39 PM
Message : info: edgelet_docker::runtime -- Querying system info...
TimeCreated : 6/7/2021 7:13:39 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:39.272295400 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 454 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:39 PM
Message : info: edgelet_docker::runtime -- Successfully queried system info
TimeCreated : 6/7/2021 7:13:40 PM
Message : info: edgelet_docker::runtime -- Querying system info...
TimeCreated : 6/7/2021 7:13:40 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:40.850249400 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 454 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:40 PM
Message : info: edgelet_docker::runtime -- Successfully queried system info
TimeCreated : 6/7/2021 7:13:40 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:40.911544300 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 571 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:41 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:13:41.038974300 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:13:42.265698300 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5385 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.456869700 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 771 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.639590400 UTC] "PUT /identities/spectrum-cloudstoreservice?api-version=2020-07-07 HTTP/1.1" 200 OK 116 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.647591500 UTC] "PUT /identities/spectrum-claimsservice?api-version=2020-07-07 HTTP/1.1" 200 OK 112 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.663584 UTC] "PUT /identities/spectrum-logservice?api-version=2020-07-07 HTTP/1.1" 200 OK 109 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.665584700 UTC] "PUT /identities/%24edgeHub?api-version=2020-07-07 HTTP/1.1" 200 OK 98 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.835819400 UTC] "PUT /identities/spectrum-pageservice?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:42.844819200 UTC] "PUT /identities/spectrum-syncservice?api-version=2020-07-07 HTTP/1.1" 200 OK 110 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:42 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25...
TimeCreated : 6/7/2021 7:13:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:13:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:13:59 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:13:59 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25
TimeCreated : 6/7/2021 7:13:59 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:13:59.324336600 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1554 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:13:59 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-claimsservice
TimeCreated : 6/7/2021 7:13:59 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:14:00 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:00.906585200 UTC] "POST /modules/spectrum-claimsservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:00 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-claimsservice
TimeCreated : 6/7/2021 7:14:00 PM
Message : info: edgelet_docker::runtime -- Pulling image mcr.microsoft.com/azureiotedge-hub:1.0...
TimeCreated : 6/7/2021 7:14:02 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:02.772998600 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:11 PM
Message : info: edgelet_docker::runtime -- Creating module edgeHub...
TimeCreated : 6/7/2021 7:14:11 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image mcr.microsoft.com/azureiotedge-hub:1.0
TimeCreated : 6/7/2021 7:14:11 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:11.576000600 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1101 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:11 PM
Message : info: edgelet_docker::runtime -- Successfully created module edgeHub
TimeCreated : 6/7/2021 7:14:11 PM
Message : info: edgelet_docker::runtime -- Starting module edgeHub...
TimeCreated : 6/7/2021 7:14:13 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:13.402106300 UTC] "POST /modules/edgeHub/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:13 PM
Message : info: edgelet_docker::runtime -- Successfully started module edgeHub
TimeCreated : 6/7/2021 7:14:13 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-pageservice:win-17763-v1.1.2...
TimeCreated : 6/7/2021 7:14:14 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:edge_hsm_client_store_create_pki_cert:2706) Generating certificate and key for alias $edgeHub637586871877407004server
TimeCreated : 6/7/2021 7:14:14 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_pki_openssl.c:generate_rsa_key:346) Generating RSA key of length 2048
TimeCreated : 6/7/2021 7:14:14 PM
Message : error: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_store.c:remove_if_cert_and_key_exist_by_alias:1443) Certificate and key file for alias do not exist $edgeHub637586871877407004server
TimeCreated : 6/7/2021 7:14:14 PM
Message : info: libiothsm -- (D:\a\1\s\edgelet\hsm-sys\azure-iot-hsm-c\src\edge_hsm_client_crypto.c:edge_hsm_client_destroy_certificate:344) Could not destroy certificate in the store for alias: $edgeHub637586871877407004server
TimeCreated : 6/7/2021 7:14:14 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:14.989712500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/certificate/server?api-version=2019-01-30 HTTP/1.1" 201 Created 9196 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:15 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:15.519080500 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:16 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:16.799335800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/sign?api-version=2019-01-30 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:16 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:16.899425600 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 397 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:17 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:17.107402400 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 372 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:17 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:17.129497100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 581 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:17 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:17.160574300 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 556 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.342516 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 753 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.368607600 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/sign?api-version=2019-01-30 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.402642300 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 765 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.414484500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 761 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.422554100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 793 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.430355 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 793 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.438120800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 789 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.445966900 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 797 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:18.454637500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 809 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.122179800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 556 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.132100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 556 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.458735100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 556 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.619961 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1457 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.802382600 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1436 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.815640900 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.890890100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.912887600 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.929888800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.945889800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.955889900 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:19 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:19.965889700 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1553 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:21 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:21.515803900 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:21 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:21.526004500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:21 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:21.843537500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:21 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:21.866755500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:21 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:14:21.874956500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:29 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:29.000352300 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5304 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:14:34 PM
Message : info: edgelet_docker::runtime -- Getting logs for module edgeHub...
TimeCreated : 6/7/2021 7:14:34 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:34.597237 UTC] "GET /modules/edgeHub/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623006874 HTTP/1.1" 200 OK - "-" "iotedge/0.1.0"
auth_id(-)
TimeCreated : 6/7/2021 7:14:34 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module edgeHub
TimeCreated : 6/7/2021 7:14:38 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:38.204111300 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5304 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:14:39 PM
Message : info: edgelet_docker::runtime -- Querying system resources...
TimeCreated : 6/7/2021 7:14:43 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:43.141851700 UTC] "GET /systeminfo/resources?api-version=2020-07-07 HTTP/1.1" 200 OK 3955 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:14:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:14:45 PM
Message : info: edgelet_docker::runtime -- Getting logs for module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:14:45 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:45.808778700 UTC] "GET /modules/spectrum-claimsservice/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623006885 HTTP/1.1" 200 OK -
"-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:14:45 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module spectrum-claimsservice
TimeCreated : 6/7/2021 7:14:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:14:52 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:14:52.281148700 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 5304 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:15:06 PM
Message : info: edgelet_docker::runtime -- Restarting module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:15:08 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:08.517921900 UTC] "POST /modules/spectrum-claimsservice/restart?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:15:08 PM
Message : info: edgelet_docker::runtime -- Successfully restarted module spectrum-claimsservice
TimeCreated : 6/7/2021 7:15:10 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:15:10.732137 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:21 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-pageservice:win-17763-v1.1.2
TimeCreated : 6/7/2021 7:15:21 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-pageservice...
TimeCreated : 6/7/2021 7:15:21 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:21.109524600 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1544 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:21 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-pageservice
TimeCreated : 6/7/2021 7:15:21 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-pageservice...
TimeCreated : 6/7/2021 7:15:22 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:22.955965800 UTC] "POST /modules/spectrum-pageservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:22 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-pageservice
TimeCreated : 6/7/2021 7:15:23 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-syncservice:win-17763-v1.1.13...
TimeCreated : 6/7/2021 7:15:24 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:15:24.775679100 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:43 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:43.849594300 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 8761 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:15:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:15:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:15:47 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-syncservice...
TimeCreated : 6/7/2021 7:15:47 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-syncservice:win-17763-v1.1.13
TimeCreated : 6/7/2021 7:15:47 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:47.725143600 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1544 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:47 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-syncservice
TimeCreated : 6/7/2021 7:15:47 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-syncservice...
TimeCreated : 6/7/2021 7:15:49 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:49.154511500 UTC] "POST /modules/spectrum-syncservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:49 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-syncservice
TimeCreated : 6/7/2021 7:15:49 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-logservice:win-17763-v1.1.2...
TimeCreated : 6/7/2021 7:15:50 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:15:50.640759900 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:15:51 PM
Message : info: edgelet_docker::runtime -- Getting logs for module spectrum-pageservice...
TimeCreated : 6/7/2021 7:15:51 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:51.518444 UTC] "GET /modules/spectrum-pageservice/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623006951 HTTP/1.1" 200 OK - "-"
"iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:15:51 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module spectrum-pageservice
TimeCreated : 6/7/2021 7:15:53 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:15:53.732337200 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 12521 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:16:11 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-logservice...
TimeCreated : 6/7/2021 7:16:11 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-logservice:win-17763-v1.1.2
TimeCreated : 6/7/2021 7:16:11 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:11.516267300 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1538 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:11 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-logservice
TimeCreated : 6/7/2021 7:16:11 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-logservice...
TimeCreated : 6/7/2021 7:16:12 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:12.957796400 UTC] "POST /modules/spectrum-logservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:12 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-logservice
TimeCreated : 6/7/2021 7:16:13 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-cloudstoreservice:win-17763-v1.0.11...
TimeCreated : 6/7/2021 7:16:15 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:15.057508300 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:35 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-cloudstoreservice:win-17763-v1.0.11
TimeCreated : 6/7/2021 7:16:35 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-cloudstoreservice...
TimeCreated : 6/7/2021 7:16:35 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-cloudstoreservice
TimeCreated : 6/7/2021 7:16:35 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:35.996424300 UTC] "POST /modules?api-version=2020-07-07 HTTP/1.1" 201 Created 1542 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:36 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-cloudstoreservice...
TimeCreated : 6/7/2021 7:16:37 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-cloudstoreservice
TimeCreated : 6/7/2021 7:16:37 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:37.442814 UTC] "POST /modules/spectrum-cloudstoreservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:37 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:37.718817100 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5385 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:38 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:38.962728100 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:43 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:43.090879700 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19066 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:43 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:16:43 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-claimsservice
TimeCreated : 6/7/2021 7:16:43 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:43.126927500 UTC] "POST /modules/spectrum-claimsservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:43 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:16:43 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:16:44 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:44.141200300 UTC] "POST /modules/spectrum-claimsservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:44 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-claimsservice
TimeCreated : 6/7/2021 7:16:44 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-pageservice...
TimeCreated : 6/7/2021 7:16:44 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-pageservice
TimeCreated : 6/7/2021 7:16:44 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:44.287618700 UTC] "POST /modules/spectrum-pageservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:44 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:16:44 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-pageservice...
TimeCreated : 6/7/2021 7:16:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:16:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:16:46 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:46.987710300 UTC] "POST /modules/spectrum-pageservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:46 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-pageservice
TimeCreated : 6/7/2021 7:16:47 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-syncservice...
TimeCreated : 6/7/2021 7:16:47 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:47.185311 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:47 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:47.186311400 UTC] "POST /modules/spectrum-syncservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:47 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:16:47 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-syncservice
TimeCreated : 6/7/2021 7:16:47 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-syncservice...
TimeCreated : 6/7/2021 7:16:49 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:49.235753 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:50 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:50.534402400 UTC] "POST /modules/spectrum-syncservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:50 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-syncservice
TimeCreated : 6/7/2021 7:16:50 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-logservice...
TimeCreated : 6/7/2021 7:16:50 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:50.655762100 UTC] "POST /modules/spectrum-logservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:50 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:16:50 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-logservice
TimeCreated : 6/7/2021 7:16:50 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-logservice...
TimeCreated : 6/7/2021 7:16:52 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:52.113263100 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:54 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:16:54.416364800 UTC] "POST /modules/spectrum-logservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:54 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-logservice
TimeCreated : 6/7/2021 7:16:55 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:55.243587600 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5385 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:16:55 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:16:55.894051800 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:00 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:00.537879100 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19126 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:06 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:06.120303200 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19140 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:11.515287300 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19147 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-cloudstoreservice...
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:11.672665500 UTC] "POST /modules/spectrum-cloudstoreservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:17:11 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-cloudstoreservice
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-cloudstoreservice...
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.762665100 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.815353800 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.833394300 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.854990700 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.876990200 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.889989200 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.906992500 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:11 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:11.980990200 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1553 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:12 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:12.013701300 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:12 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:12.030554400 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:12 PM
Message : error: edgelet_http -- server connection error: (unknown)
TimeCreated : 6/7/2021 7:17:12 PM
Message : error: edgelet_utils::logging -- error writing a body to connection: An existing connection was forcibly closed by the remote host. (os error 10054)
TimeCreated : 6/7/2021 7:17:12 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:12.520601300 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1528 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:12 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:12.607333 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1273 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:12 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:12.655268700 UTC] "POST /modules/%24edgeHub/genid/637586871877407004/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 1252 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:13 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-cloudstoreservice
TimeCreated : 6/7/2021 7:17:13 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:13.032991700 UTC] "POST /modules/spectrum-cloudstoreservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:13 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:13.577914100 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5385 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:14 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:14.760744200 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:18 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:18.500884900 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19147 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:18 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:18.863383700 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19147 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:18 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:18.922277600 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5413 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:19 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:19.576182400 UTC] "GET /identities/?api-version=2020-07-07 HTTP/1.1" 200 OK 771 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:19 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:19.736122300 UTC] "PUT /identities/spectrum-claimsservice?api-version=2020-07-07 HTTP/1.1" 200 OK 112 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:19 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25-bugfix-timeout2.15...
TimeCreated : 6/7/2021 7:17:22 PM
Message : info: edgelet_docker::runtime -- Getting logs for module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:22 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:22.520600 UTC] "GET /modules/spectrum-claimsservice/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623007042 HTTP/1.1" 200 OK - "-"
"iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:22 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:23 PM
Message : info: edgelet_docker::runtime -- Getting logs for module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:23 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:23 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:23.979006400 UTC] "GET /modules/spectrum-claimsservice/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623007043 HTTP/1.1" 200 OK -
"-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:24 PM
Message : info: edgelet_docker::runtime -- Getting logs for module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:24 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:24.965236200 UTC] "GET /modules/spectrum-claimsservice/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623007044 HTTP/1.1" 200 OK -
"-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:24 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:26 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:26.228918500 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19147 "-" "iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:29 PM
Message : info: edgelet_docker::runtime -- Getting logs for module edgeHub...
TimeCreated : 6/7/2021 7:17:29 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:29.369835200 UTC] "GET /modules/edgeHub/logs?api-version=2020-07-07&follow=true&tail=all×tamps=false&since=1623007049 HTTP/1.1" 200 OK - "-"
"iotedge/0.1.0" auth_id(-)
TimeCreated : 6/7/2021 7:17:29 PM
Message : info: edgelet_docker::runtime -- Successfully got logs for module edgeHub
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:39.448036900 UTC] "POST /modules/spectrum-claimsservice/prepareupdate?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25-bugfix-timeout2.15
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:39.451564400 UTC] "POST /modules/spectrum-claimsservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:39 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:17:39 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_http_mgmt::server::module::update -- Updating module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_docker::runtime -- Removing module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_docker::runtime -- Pulling image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25-bugfix-timeout2.15...
TimeCreated : 6/7/2021 7:17:39 PM
Message : info: edgelet_docker::runtime -- Successfully removed module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:41 PM
Message : info: edgelet_docker::runtime -- Creating module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:41 PM
Message : info: edgelet_docker::runtime -- Successfully pulled image edgemodulesacrqa.azurecr.io/spectrum-claimsservice:win-17763-v1.0.25-bugfix-timeout2.15
TimeCreated : 6/7/2021 7:17:41 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:41.489720600 UTC] "PUT /modules/spectrum-claimsservice?api-version=2020-07-07 HTTP/1.1" 200 OK 1573 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:41 PM
Message : info: edgelet_docker::runtime -- Successfully created module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:41 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-claimsservice...
TimeCreated : 6/7/2021 7:17:42 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-claimsservice
TimeCreated : 6/7/2021 7:17:42 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:42.949416 UTC] "POST /modules/spectrum-claimsservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:43 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:43.154902800 UTC] "POST /modules/%24edgeAgent/genid/637586871877407004/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 5413 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:43 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:43.750730700 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:45 PM
Message : info: edgelet_core::watchdog -- Checking edge runtime status
TimeCreated : 6/7/2021 7:17:45 PM
Message : info: edgelet_core::watchdog -- Edge runtime is running.
TimeCreated : 6/7/2021 7:17:48 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:48.456305200 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 19282 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:48 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-pageservice...
TimeCreated : 6/7/2021 7:17:48 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:48.530305900 UTC] "POST /modules/spectrum-pageservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:48 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:17:48 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-pageservice
TimeCreated : 6/7/2021 7:17:48 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-pageservice...
TimeCreated : 6/7/2021 7:17:49 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:49.757340700 UTC] "POST /modules/spectrum-pageservice/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:49 PM
Message : info: edgelet_docker::runtime -- Successfully started module spectrum-pageservice
TimeCreated : 6/7/2021 7:17:49 PM
Message : info: edgelet_docker::runtime -- Stopping module spectrum-syncservice...
TimeCreated : 6/7/2021 7:17:49 PM
Message : info: edgelet_http::logging -- [mgmt] - - - [2021-06-07 19:17:49.858974900 UTC] "POST /modules/spectrum-syncservice/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
TimeCreated : 6/7/2021 7:17:49 PM
Message : warn: edgelet_utils::logging -- caused by: Target of operation already in this state
TimeCreated : 6/7/2021 7:17:49 PM
Message : warn: edgelet_utils::logging -- Could not stop module spectrum-syncservice
TimeCreated : 6/7/2021 7:17:49 PM
Message : info: edgelet_docker::runtime -- Starting module spectrum-syncservice...
TimeCreated : 6/7/2021 7:17:51 PM
Message : info: edgelet_http::logging -- [work] - - - [2021-06-07 19:17:51.474337300 UTC] "GET /trust-bundle?api-version=2018-06-28 HTTP/1.1" 200 OK 1936 "-" "-" auth_id(-)
edge-agent logs
2021-06-07 19:13:37.480 +00:00 Edge Agent Main()
<6> 2021-06-07 19:13:38.258 +00:00 [INF] - Initializing Edge Agent.
<6> 2021-06-07 19:13:38.639 +00:00 [INF] - Version - 1.0.10.4.37804714 (57772714c81c8b823a5ef05bf11bf343b923fb6a)
<6> 2021-06-07 19:13:38.639 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝
██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝
<6> 2021-06-07 19:13:38.676 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2021-06-07 19:13:38.933 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:9/5/2021 7:11:43 PM] to CertificateAuthority
<6> 2021-06-07 19:13:39.045 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics
<6> 2021-06-07 19:13:39.238 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2021-06-07 19:13:39.242 +00:00 [INF] - Started operation Get system resources
<6> 2021-06-07 19:13:39.244 +00:00 [INF] - Collecting metadata metrics
<6> 2021-06-07 19:13:39.301 +00:00 [INF] - Set metadata metrics: 1.0.10.4.37804714 (57772714c81c8b823a5ef05bf11bf343b923fb6a), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"windows","Architecture":"x86_64","Version":"1.1.3 (68e71a5384b14956775241557877497274d0ce7e)","Provisioning":{"Type":"manual.device_connection_string","DynamicReprovisioning":false},"ServerVersion":"19.03.12+azure","KernelVersion":"10.0 17763 (17763.1.amd64fre.rs5_release.180914-1434)","OperatingSystem":"Windows Server 2019 Datacenter Version 1809 (OS Build 17763.1935)","NumCpus":1,"Virtualized":"unknown"}, True
<6> 2021-06-07 19:13:39.318 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2021-06-07 19:13:39.331 +00:00 [INF] - Started operation refresh twin config
<6> 2021-06-07 19:13:39.347 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<6> 2021-06-07 19:13:39.840 +00:00 [INF] - Created persistent store at C:\Windows\TEMP\edgeAgent
<6> 2021-06-07 19:13:39.896 +00:00 [INF] - Started operation Metrics Scrape
<6> 2021-06-07 19:13:39.896 +00:00 [INF] - Started operation Metrics Upload
Scraping frequency: 01:00:00
Upload Frequency: 1.00:00:00
<6> 2021-06-07 19:13:40.853 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2021-06-07 19:13:40.853 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2021-06-07 19:13:40.853 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2021-06-07 19:13:40.853 +00:00 [INF] - Registering request handler RestartModule
<6> 2021-06-07 19:13:41.692 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only.
<6> 2021-06-07 19:13:42.011 +00:00 [INF] - Initialized new module client with subscriptions enabled
<6> 2021-06-07 19:13:42.179 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 2 and reported properties version 60.
<6> 2021-06-07 19:13:42.938 +00:00 [INF] - Plan execution started for deployment 2
<6> 2021-06-07 19:13:42.954 +00:00 [INF] - Executing command: "Command Group: (\n [Create module spectrum-claimsservice]\n [Start module spectrum-claimsservice]\n)"
<6> 2021-06-07 19:13:42.957 +00:00 [INF] - Executing command: "Create module spectrum-claimsservice"
<6> 2021-06-07 19:13:59.331 +00:00 [INF] - Executing command: "Start module spectrum-claimsservice"
<6> 2021-06-07 19:14:00.918 +00:00 [INF] - Executing command: "Command Group: (\n [Create module edgeHub]\n [Start module edgeHub]\n)"
<6> 2021-06-07 19:14:00.918 +00:00 [INF] - Executing command: "Create module edgeHub"
<6> 2021-06-07 19:14:11.578 +00:00 [INF] - Executing command: "Start module edgeHub"
<6> 2021-06-07 19:14:13.408 +00:00 [INF] - Executing command: "Command Group: (\n [Create module spectrum-pageservice]\n [Start module spectrum-pageservice]\n)"
<6> 2021-06-07 19:14:13.409 +00:00 [INF] - Executing command: "Create module spectrum-pageservice"
<6> 2021-06-07 19:15:21.111 +00:00 [INF] - Executing command: "Start module spectrum-pageservice"
<6> 2021-06-07 19:15:22.958 +00:00 [INF] - Executing command: "Command Group: (\n [Create module spectrum-syncservice]\n [Start module spectrum-syncservice]\n)"
<6> 2021-06-07 19:15:22.958 +00:00 [INF] - Executing command: "Create module spectrum-syncservice"
<6> 2021-06-07 19:15:47.731 +00:00 [INF] - Executing command: "Start module spectrum-syncservice"
<6> 2021-06-07 19:15:49.162 +00:00 [INF] - Executing command: "Command Group: (\n [Create module spectrum-logservice]\n [Start module spectrum-logservice]\n)"
<6> 2021-06-07 19:15:49.162 +00:00 [INF] - Executing command: "Create module spectrum-logservice"
<6> 2021-06-07 19:16:11.518 +00:00 [INF] - Executing command: "Start module spectrum-logservice"
<6> 2021-06-07 19:16:12.959 +00:00 [INF] - Executing command: "Command Group: (\n [Create module spectrum-cloudstoreservice]\n [Start module spectrum-cloudstoreservice]\n)"
<6> 2021-06-07 19:16:12.960 +00:00 [INF] - Executing command: "Create module spectrum-cloudstoreservice"
<6> 2021-06-07 19:16:35.998 +00:00 [INF] - Executing command: "Start module spectrum-cloudstoreservice"
<6> 2021-06-07 19:16:37.444 +00:00 [INF] - Plan execution ended for deployment 2
<6> 2021-06-07 19:16:38.058 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:16:43.111 +00:00 [INF] - Plan execution started for deployment 2
<6> 2021-06-07 19:16:43.112 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-claimsservice]\n [Start module spectrum-claimsservice]\n [Saving spectrum-claimsservice to store]\n)"
<6> 2021-06-07 19:16:43.112 +00:00 [INF] - Executing command: "Stop module spectrum-claimsservice"
<6> 2021-06-07 19:16:43.144 +00:00 [INF] - Executing command: "Start module spectrum-claimsservice"
<6> 2021-06-07 19:16:44.142 +00:00 [INF] - Executing command: "Saving spectrum-claimsservice to store"
<6> 2021-06-07 19:16:44.149 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-pageservice]\n [Start module spectrum-pageservice]\n [Saving spectrum-pageservice to store]\n)"
<6> 2021-06-07 19:16:44.149 +00:00 [INF] - Executing command: "Stop module spectrum-pageservice"
<6> 2021-06-07 19:16:44.288 +00:00 [INF] - Executing command: "Start module spectrum-pageservice"
<6> 2021-06-07 19:16:46.988 +00:00 [INF] - Executing command: "Saving spectrum-pageservice to store"
<6> 2021-06-07 19:16:47.006 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-syncservice]\n [Start module spectrum-syncservice]\n [Saving spectrum-syncservice to store]\n)"
<6> 2021-06-07 19:16:47.007 +00:00 [INF] - Executing command: "Stop module spectrum-syncservice"
<6> 2021-06-07 19:16:47.195 +00:00 [INF] - Executing command: "Start module spectrum-syncservice"
<6> 2021-06-07 19:16:50.535 +00:00 [INF] - Executing command: "Saving spectrum-syncservice to store"
<6> 2021-06-07 19:16:50.536 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-logservice]\n [Start module spectrum-logservice]\n [Saving spectrum-logservice to store]\n)"
<6> 2021-06-07 19:16:50.536 +00:00 [INF] - Executing command: "Stop module spectrum-logservice"
<6> 2021-06-07 19:16:50.657 +00:00 [INF] - Executing command: "Start module spectrum-logservice"
<6> 2021-06-07 19:16:54.417 +00:00 [INF] - Executing command: "Saving spectrum-logservice to store"
<6> 2021-06-07 19:16:54.425 +00:00 [INF] - Plan execution ended for deployment 2
<6> 2021-06-07 19:16:55.511 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:17:00.549 +00:00 [INF] - Module 'spectrum-cloudstoreservice' scheduled to restart after 10s (05s left).
<6> 2021-06-07 19:17:00.811 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:17:06.128 +00:00 [INF] - Module 'spectrum-claimsservice' scheduled to restart after 20s (16s left).
<6> 2021-06-07 19:17:06.128 +00:00 [INF] - Module 'spectrum-pageservice' scheduled to restart after 20s (18s left).
<6> 2021-06-07 19:17:06.128 +00:00 [INF] - Module 'spectrum-cloudstoreservice' scheduled to restart after 10s (00s left).
<6> 2021-06-07 19:17:06.392 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Module 'spectrum-claimsservice' scheduled to restart after 20s (10s left).
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Module 'spectrum-pageservice' scheduled to restart after 20s (13s left).
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Module 'spectrum-syncservice' scheduled to restart after 20s (15s left).
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Plan execution started for deployment 2
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-cloudstoreservice]\n [Start module spectrum-cloudstoreservice]\n [Saving spectrum-cloudstoreservice to store]\n)"
<6> 2021-06-07 19:17:11.642 +00:00 [INF] - Executing command: "Stop module spectrum-cloudstoreservice"
<6> 2021-06-07 19:17:11.674 +00:00 [INF] - Executing command: "Start module spectrum-cloudstoreservice"
<6> 2021-06-07 19:17:13.033 +00:00 [INF] - Executing command: "Saving spectrum-cloudstoreservice to store"
<6> 2021-06-07 19:17:13.037 +00:00 [INF] - Plan execution ended for deployment 2
<6> 2021-06-07 19:17:13.848 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:17:19.760 +00:00 [INF] - Module 'spectrum-pageservice' scheduled to restart after 20s (04s left).
<6> 2021-06-07 19:17:19.760 +00:00 [INF] - Module 'spectrum-syncservice' scheduled to restart after 20s (07s left).
<6> 2021-06-07 19:17:19.760 +00:00 [INF] - Module 'spectrum-logservice' scheduled to restart after 20s (11s left).
<6> 2021-06-07 19:17:19.760 +00:00 [INF] - Plan execution started for deployment 3
<6> 2021-06-07 19:17:19.761 +00:00 [INF] - Executing command: "Saving spectrum-claimsservice to store"
<6> 2021-06-07 19:17:19.763 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module spectrum-claimsservice]\n [Stop module spectrum-claimsservice]\n [Update module spectrum-claimsservice]\n)]\n [Start module spectrum-claimsservice]\n)"
<6> 2021-06-07 19:17:19.763 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module spectrum-claimsservice]\n [Stop module spectrum-claimsservice]\n [Update module spectrum-claimsservice]\n)"
<6> 2021-06-07 19:17:41.494 +00:00 [INF] - Executing command: "Start module spectrum-claimsservice"
<6> 2021-06-07 19:17:42.950 +00:00 [INF] - Plan execution ended for deployment 3
<6> 2021-06-07 19:17:43.443 +00:00 [INF] - Updated reported properties
<6> 2021-06-07 19:17:48.463 +00:00 [INF] - Module 'spectrum-cloudstoreservice' scheduled to restart after 20s (01s left).
<6> 2021-06-07 19:17:48.464 +00:00 [INF] - Plan execution started for deployment 3
<6> 2021-06-07 19:17:48.464 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-pageservice]\n [Start module spectrum-pageservice]\n [Saving spectrum-pageservice to store]\n)"
<6> 2021-06-07 19:17:48.464 +00:00 [INF] - Executing command: "Stop module spectrum-pageservice"
<6> 2021-06-07 19:17:48.531 +00:00 [INF] - Executing command: "Start module spectrum-pageservice"
<6> 2021-06-07 19:17:49.758 +00:00 [INF] - Executing command: "Saving spectrum-pageservice to store"
<6> 2021-06-07 19:17:49.762 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module spectrum-syncservice]\n [Start module spectrum-syncservice]\n [Saving spectrum-syncservice to store]\n)"
<6> 2021-06-07 19:17:49.762 +00:00 [INF] - Executing command: "Stop module spectrum-syncservice"
<6> 2021-06-07 19:17:49.860 +00:00 [INF] - Executing command: "Start module spectrum-syncservice"
edge-hub logs
2021-06-07 19:14:13.422 +00:00 Edge Hub Main()
<6> 2021-06-07 19:14:15.552 +00:00 [INF] - Installing certificates [CN=iotedged workload ca:9/5/2021 7:11:43 PM],[CN=Test Edge Device CA:9/5/2021 7:11:43 PM],[CN=Test Edge Owner CA:9/5/2021 7:11:43 PM] to CertificateAuthority
<6> 2021-06-07 19:14:15.593 +00:00 [INF] - Installing certificates [CN=Test Edge Owner CA:9/5/2021 7:11:43 PM] to CertificateAuthority
<6> 2021-06-07 19:14:15.598 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12
<6> 2021-06-07 19:14:15.848 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false}
<6> 2021-06-07 19:14:16.243 +00:00 [INF] - Created persistent store at C:\Windows\TEMP\edgeHub
<6> 2021-06-07 19:14:16.273 +00:00 [INF] - Initializing Edge Hub
<6> 2021-06-07 19:14:16.273 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝
██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝
<6> 2021-06-07 19:14:16.274 +00:00 [INF] - Version - 1.0.10.4.37804714 (57772714c81c8b823a5ef05bf11bf343b923fb6a)
<6> 2021-06-07 19:14:16.274 +00:00 [INF] - OptimizeForPerformance=True
<6> 2021-06-07 19:14:16.274 +00:00 [INF] - MessageAckTimeoutSecs=30
<6> 2021-06-07 19:14:16.275 +00:00 [INF] - Loaded server certificate with expiration date of "2021-09-05T19:11:43.0000000+00:00"
<6> 2021-06-07 19:14:16.299 +00:00 [INF] - Using Asp Net server for metrics
<6> 2021-06-07 19:14:16.327 +00:00 [INF] - Created device scope identities cache
<6> 2021-06-07 19:14:16.347 +00:00 [INF] - Starting refresh of device scope identities cache
<6> 2021-06-07 19:14:16.389 +00:00 [INF] - Created new message store
<6> 2021-06-07 19:14:16.398 +00:00 [INF] - Started task to cleanup processed and stale messages
<6> 2021-06-07 19:14:16.454 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00
<6> 2021-06-07 19:14:16.495 +00:00 [INF] - Initialized storing twin manager
<6> 2021-06-07 19:14:16.512 +00:00 [INF] - Initializing configuration
<6> 2021-06-07 19:14:16.520 +00:00 [INF] - New device connection for device 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:14:16.525 +00:00 [INF] - Client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub connected to edgeHub, processing existing subscriptions.
<6> 2021-06-07 19:14:16.604 +00:00 [INF] - Attempting to connect to IoT Hub for client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub via AMQP over WebSockets...
<6> 2021-06-07 19:14:16.750 +00:00 [INF] - Processing pending subscriptions for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<4> 2021-06-07 19:14:17.167 +00:00 [WRN] - Empty edge hub configuration received. Ignoring...
<6> 2021-06-07 19:14:19.033 +00:00 [INF] - Exiting disconnected state
<6> 2021-06-07 19:14:19.043 +00:00 [INF] - Received device connected callback
<6> 2021-06-07 19:14:19.046 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients.
<6> 2021-06-07 19:14:19.046 +00:00 [INF] - Processing subscriptions for client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub on device connected to cloud.
<6> 2021-06-07 19:14:19.047 +00:00 [INF] - Skipping 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-07 19:14:19.051 +00:00 [INF] - Entering connected state
<6> 2021-06-07 19:14:19.053 +00:00 [INF] - Cloud connection for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub is True
<6> 2021-06-07 19:14:19.054 +00:00 [INF] - Connection status for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub changed to ConnectionEstablished
<6> 2021-06-07 19:14:19.055 +00:00 [INF] - Client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub connected to cloud, processing existing subscriptions.
<6> 2021-06-07 19:14:19.055 +00:00 [INF] - Skipping 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub for subscription processing, as it is currently being processed.
<6> 2021-06-07 19:14:19.056 +00:00 [INF] - Created cloud proxy for client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub via AMQP over WebSockets, with client operation timeout 20 seconds.
<6> 2021-06-07 19:14:19.058 +00:00 [INF] - Initialized cloud proxy 8150027b-d113-478e-9821-153b24920069 for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:14:19.058 +00:00 [INF] - Created cloud connection for client 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:14:19.415 +00:00 [INF] - Processing pending subscriptions for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:14:19.508 +00:00 [INF] - Updated reported properties for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:14:19.751 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10.
<6> 2021-06-07 19:14:19.967 +00:00 [INF] - Obtained edge hub config from module twin
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - Set the following 5 route(s) in edge hub
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - spectrum-syncserviceIoTHub: FROM /messages/modules/spectrum-syncservice/* INTO $upstream
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - spectrum-pageserviceIoTHub: FROM /messages/modules/spectrum-pageservice/* INTO $upstream
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - spectrum-logserviceIoTHub: FROM /messages/modules/spectrum-logservice/* INTO $upstream
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - spectrum-claimsserviceIoTHub: FROM /messages/modules/spectrum-claimsservice/* INTO $upstream
<6> 2021-06-07 19:14:20.094 +00:00 [INF] - spectrum-cloudstoreserviceIoTHub: FROM /messages/modules/spectrum-cloudstoreservice/* INTO $upstream
<6> 2021-06-07 19:14:20.095 +00:00 [INF] - Updated message store TTL to 7200 seconds
<6> 2021-06-07 19:14:20.095 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-07 19:14:20.099 +00:00 [INF] - Started operation Get EdgeHub config
<6> 2021-06-07 19:14:20.100 +00:00 [INF] - Initialized edge hub configuration
<6> 2021-06-07 19:14:20.104 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds
<6> 2021-06-07 19:14:20.157 +00:00 [INF] - Scheduling server certificate renewal for "2021-09-05T19:09:13.0000679Z".
<6> 2021-06-07 19:14:20.157 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-06-07 19:14:20.163 +00:00 [INF] - Starting MQTT head
<6> 2021-06-07 19:14:20.190 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head.
<6> 2021-06-07 19:14:20.242 +00:00 [INF] - Starting AMQP head
<6> 2021-06-07 19:14:20.320 +00:00 [INF] - Started AMQP head
<6> 2021-06-07 19:14:20.327 +00:00 [INF] - Starting HTTP head
<4> 2021-06-07 19:14:20.475 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead.
<6> 2021-06-07 19:14:20.485 +00:00 [INF] - Started HTTP head
<6> 2021-06-07 19:14:20.520 +00:00 [INF] - Started MQTT head
<6> 2021-06-07 19:14:21.820 +00:00 [INF] - Updated reported properties for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<6> 2021-06-07 19:17:11.860 +00:00 [INF] - Obtained edge hub config patch update from module twin
<6> 2021-06-07 19:17:11.989 +00:00 [INF] - Updating edge hub configuration
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - Set the following 5 route(s) in edge hub
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - spectrum-syncserviceIoTHub: FROM /messages/modules/spectrum-syncservice/* INTO $upstream
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - spectrum-pageserviceIoTHub: FROM /messages/modules/spectrum-pageservice/* INTO $upstream
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - spectrum-logserviceIoTHub: FROM /messages/modules/spectrum-logservice/* INTO $upstream
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - spectrum-claimsserviceIoTHub: FROM /messages/modules/spectrum-claimsservice/* INTO $upstream
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - spectrum-cloudstoreserviceIoTHub: FROM /messages/modules/spectrum-cloudstoreservice/* INTO $upstream
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - Updated message store TTL to 7200 seconds
<6> 2021-06-07 19:17:12.003 +00:00 [INF] - Updated the edge hub store and forward configuration
<6> 2021-06-07 19:17:12.317 +00:00 [INF] - Updated reported properties for 946b65b2-2aed-481d-b67e-29a189a19201::62c9f3dc-24f9-43e1-a4e2-725f6de1c4f7/$edgeHub
<3> 2021-06-07 19:17:45.536 +00:00 [ERR] - Unhandled exception while processing "0HM99T3N38MQH".
System.ComponentModel.Win32Exception (0x8009030D): The credentials supplied to the package were not recognized
at System.Net.SSPIWrapper.AcquireCredentialsHandle(SSPIInterface secModule, String package, CredentialUse intent, SCHANNEL_CRED scc)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(CredentialUse credUsage, SCHANNEL_CRED secureCredential)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(X509Certificate certificate, SslProtocols protocols, EncryptionPolicy policy, Boolean isServer)
at System.Net.Security.SecureChannel.AcquireServerCredentials(Byte[]& thumbPrint, Byte[] clientHello)
at System.Net.Security.SecureChannel.GenerateToken(Byte[] input, Int32 offset, Int32 count, Byte[]& output)
at System.Net.Security.SecureChannel.NextMessage(Byte[] incoming, Int32 offset, Int32 count)
at System.Net.Security.SslStream.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.ProcessAuthentication(LazyAsyncResult lazyResult, CancellationToken cancellationToken)
at System.Net.Security.SslStream.BeginAuthenticateAsServer(SslServerAuthenticationOptions sslServerAuthenticationOptions, CancellationToken cancellationToken, AsyncCallback asyncCallback, Object asyncState)
at System.Net.Security.SslStream.<>c.<AuthenticateAsServerAsync>b__69_0(SslServerAuthenticationOptions arg1, CancellationToken arg2, AsyncCallback callback, Object state)
at System.Threading.Tasks.TaskFactory`1.FromAsyncImpl[TArg1,TArg2](Func`5 beginMethod, Func`2 endFunction, Action`1 endAction, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2](Func`5 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, Object state, TaskCreationOptions creationOptions)
at System.Threading.Tasks.TaskFactory.FromAsync[TArg1,TArg2](Func`5 beginMethod, Action`1 endMethod, TArg1 arg1, TArg2 arg2, Object state)
at System.Net.Security.SslStream.AuthenticateAsServerAsync(SslServerAuthenticationOptions sslServerAuthenticationOptions, CancellationToken cancellationToken)
at Microsoft.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.InnerOnConnectionAsync(ConnectionContext context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection.ExecuteAsync()
<3> 2021-06-07 19:17:47.562 +00:00 [ERR] - Unhandled exception while processing "0HM99T3N38MQI".
System.ComponentModel.Win32Exception (0x8009030D): The credentials supplied to the package were not recognized
at System.Net.SSPIWrapper.AcquireCredentialsHandle(SSPIInterface secModule, String package, CredentialUse intent, SCHANNEL_CRED scc)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(CredentialUse credUsage, SCHANNEL_CRED secureCredential)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(X509Certificate certificate, SslProtocols protocols, EncryptionPolicy policy, Boolean isServer)
at System.Net.Security.SecureChannel.AcquireServerCredentials(Byte[]& thumbPrint, Byte[] clientHello)
at System.Net.Security.SecureChannel.GenerateToken(Byte[] input, Int32 offset, Int32 count, Byte[]& output)
at System.Net.Security.SecureChannel.NextMessage(Byte[] incoming, Int32 offset, Int32 count)
at System.Net.Security.SslStream.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.PartialFrameCallback(AsyncProtocolRequest asyncRequest)
--- End of stack trace from previous location where exception was thrown ---
at System.Net.Security.SslStream.EndProcessAuthentication(IAsyncResult result)
at System.Net.Security.SslStream.<>c.<AuthenticateAsServerAsync>b__69_1(IAsyncResult iar)
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.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.InnerOnConnectionAsync(ConnectionContext context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection.ExecuteAsync()
<3> 2021-06-07 19:17:51.288 +00:00 [ERR] - Unhandled exception while processing "0HM99T3N38MQJ".
System.ComponentModel.Win32Exception (0x8009030D): The credentials supplied to the package were not recognized
at System.Net.SSPIWrapper.AcquireCredentialsHandle(SSPIInterface secModule, String package, CredentialUse intent, SCHANNEL_CRED scc)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(CredentialUse credUsage, SCHANNEL_CRED secureCredential)
at System.Net.Security.SslStreamPal.AcquireCredentialsHandle(X509Certificate certificate, SslProtocols protocols, EncryptionPolicy policy, Boolean isServer)
at System.Net.Security.SecureChannel.AcquireServerCredentials(Byte[]& thumbPrint, Byte[] clientHello)
at System.Net.Security.SecureChannel.GenerateToken(Byte[] input, Int32 offset, Int32 count, Byte[]& output)
at System.Net.Security.SecureChannel.NextMessage(Byte[] incoming, Int32 offset, Int32 count)
at System.Net.Security.SslStream.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security.SslStream.PartialFrameCallback(AsyncProtocolRequest asyncRequest)
--- End of stack trace from previous location where exception was thrown ---
at System.Net.Security.SslStream.EndProcessAuthentication(IAsyncResult result)
at System.Net.Security.SslStream.<>c.<AuthenticateAsServerAsync>b__69_1(IAsyncResult iar)
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.AspNetCore.Server.Kestrel.Https.Internal.HttpsConnectionMiddleware.InnerOnConnectionAsync(ConnectionContext context)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.KestrelConnection.ExecuteAsync()
Additional Information
It’s difficult to say for certain, but it feels like this issue happens more frequently with several modules (for this test I had 5), and on more resource-contrained machines (for this test I used an Azure Standard DS1 v2 VM).
About this issue
- Original URL
- State: closed
- Created 3 years ago
- Comments: 25 (12 by maintainers)
@andrewhickman ok, thanks for testing it. Although one of my colleagues was able to repro what you see earlier (using a certificate from dotnet code, it said it did not have the corresponding private key, but the 200ms later repeating the operation it worked), myself I did not see it, only that other operations were very slow. At this moment I assume that the certificate problem is related to the performance problem and we continue the investigation that direction (why win server has performance issues)
Thanks for the updated logs, I was able to reproduce it and I am investigating the root cause.
I created another support bundle while the module was failing to connect
support_bundle.zip
I set
RuntimeLogLeveltoverboseand reproduced the issue again. As before, I installed iotedge, waited formodule1to fail to connect, then raniotedge restart edgeHuband waited for it to connect successfullysupport_bundle.zip
Thanks, I hadn’t spotted the outdated images. I’ll retest with the latest versions