iotedge: Connections refused (err 111) connecting to unix:///var/run/iotedge/workload.sock after edgeAgent restart
Expected Behavior
After restarting edgeAgent via iotedge restart edgeAgent
all modules should eventually restart successfully without any further intervention.
Current Behavior
Following an iotedge restart edgeAgent
command, modules that connect to unix:///var/run/iotedge/workload.sock are unable to do so and fail with a 111 error. This includes edgeHub, the Azure Blob Storage container, and custom Python modules using the Azure IoT Python SDK. The failing modules will never recover without manual intervention - one workaround I found is to modify /etc/iotedge/config.yml
and then sudo systemctl restart iotedge
.
Steps to Reproduce
Given that no one else has reported this as an issue, it seems unlikely my repro steps will lead to a repro for others. That said, the repro steps on my systems are simple:
- Restart edgeAgent via
iotedge restart edgeAgent
. - Observe modules failing with 111 errors.
Context (Environment)
Output of iotedge check
Click here
Configuration checks
--------------------
√ config.yaml is well-formed - OK
√ config.yaml has well-formed connection string - OK
√ container engine is installed and functional - OK
√ config.yaml has correct hostname - OK
√ config.yaml has correct URIs for daemon mgmt endpoint - OK
√ latest security daemon - OK
√ host time is close to real time - OK
√ container time is close to host time - OK
√ DNS server - OK
√ production readiness: certificates - OK
√ production readiness: container engine - OK
√ production readiness: logs policy - OK
√ production readiness: Edge Agent's storage directory is persisted on the host filesystem - OK
√ production readiness: Edge Hub's storage directory is persisted on the host filesystem - OK
Connectivity checks
-------------------
√ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK
√ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK
√ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK
√ container on the default network can connect to IoT Hub AMQP port - OK
√ container on the default network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the default network can connect to IoT Hub MQTT port - OK
√ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK
√ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK
√ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK
23 check(s) succeeded.
Device Information
- Host OS [e.g. Ubuntu 18.04, Windows Server IoT 2019]: Ubuntu 18.04
- Architecture [e.g. amd64, arm32, arm64]: amd64
- Container OS [e.g. Linux containers, Windows containers]: Linux
Runtime Versions
- aziot-edged [run
iotedge version
]: iotedge 1.1.6 - Edge Agent [image tag (e.g. 1.0.0)]: azureiotedge-agent:1.1.5-linux-amd64
- Edge Hub [image tag (e.g. 1.0.0)]: azureiotedge-hub:1.1.5-linux-amd64
- Docker/Moby [run
docker version
]: Client: Version: 20.10.8+azure API version: 1.41 Go version: go1.16.7 Git commit: 3967b7d28e15a020e4ee344283128ead633b3e0c Built: Thu Jul 29 13:55:47 2021 OS/Arch: linux/amd64 Context: default Experimental: true
Server: Engine: Version: 20.10.8+azure API version: 1.41 (minimum version 1.12) Go version: go1.16.7 Git commit: 75249d88bc107a122b503f6a50e89c994331867c Built: Fri Jul 30 01:30:57 2021 OS/Arch: linux/amd64 Experimental: false containerd: Version: 1.4.9+azure GitCommit: e25210fe30a0a703442421b0f60afac609f950a3 runc: Version: 1.0.1 GitCommit: 4144b63817ebcc5b358fc2c8ef95f7cddd709aa7 docker-init: Version: 0.19.0 GitCommit:
Note: when using Windows containers on Windows, run docker -H npipe:////./pipe/iotedge_moby_engine version
instead
Logs
aziot-edged logs
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Restarting module edgeAgent...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - [mgmt] - - - [2021-09-14 17:16:29.965426236 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10019 "-" "-" auth_id(-)
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module redisiotedge...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module MetaAnalyzer...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module WindowMerger...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module EdaApp...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module mongodb...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module blobstorageiotedge...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module BlobStorageManager...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module MessageLogger...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module EdaCacher...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module AnomalyChecker...
Sep 14 17:16:29 iotedge01 iotedged[11743]: 2021-09-14T17:16:29Z [INFO] - Stopping module edgeHub...
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [work] - - - [2021-09-14 17:16:30.113108162 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4004 "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [work] - - - [2021-09-14 17:16:30.331472323 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4033 "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Successfully stoppedmodule redisiotedge
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Stopping listener for module redisiotedge
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [mgmt] - - - [2021-09-14 17:16:30.674631631 UTC] "POST /modules/redisiotedge/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [work] - - - [2021-09-14 17:16:30.713207101 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4008 "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Successfully stoppedmodule mongodb
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Stopping listener for module mongodb
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [mgmt] - - - [2021-09-14 17:16:30.783156360 UTC] "POST /modules/mongodb/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Stopping listener for module WindowMerger
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Successfully stoppedmodule WindowMerger
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [mgmt] - - - [2021-09-14 17:16:30.816223437 UTC] "POST /modules/WindowMerger/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [work] - - - [2021-09-14 17:16:30.913401935 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4341 "-" "-" auth_id(-)
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Stopping listener for module AnomalyChecker
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - Successfully stoppedmodule AnomalyChecker
Sep 14 17:16:30 iotedge01 iotedged[11743]: 2021-09-14T17:16:30Z [INFO] - [mgmt] - - - [2021-09-14 17:16:30.958810945 UTC] "POST /modules/AnomalyChecker/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - Successfully stoppedmodule MetaAnalyzer
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - Stopping listener for module MetaAnalyzer
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [mgmt] - - - [2021-09-14 17:16:31.054647034 UTC] "POST /modules/MetaAnalyzer/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - Stopping listener for module MessageLogger
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - Successfully stoppedmodule MessageLogger
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [mgmt] - - - [2021-09-14 17:16:31.098274808 UTC] "POST /modules/MessageLogger/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.212486463 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4320 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.235360998 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4320 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.409080429 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4320 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.611267527 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4345 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.912794147 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4324 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.936775943 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4037 "-" "-" auth_id(-)
Sep 14 17:16:31 iotedge01 iotedged[11743]: 2021-09-14T17:16:31Z [INFO] - [work] - - - [2021-09-14 17:16:31.957536009 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4012 "-" "-" auth_id(-)
Sep 14 17:16:32 iotedge01 iotedged[11743]: 2021-09-14T17:16:32Z [INFO] - [work] - - - [2021-09-14 17:16:32.112554332 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4012 "-" "-" auth_id(-)
Sep 14 17:16:32 iotedge01 iotedged[11743]: 2021-09-14T17:16:32Z [INFO] - [work] - - - [2021-09-14 17:16:32.323273763 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4353 "-" "-" auth_id(-)
Sep 14 17:16:32 iotedge01 iotedged[11743]: 2021-09-14T17:16:32Z [INFO] - [work] - - - [2021-09-14 17:16:32.808439723 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4328 "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [work] - - - [2021-09-14 17:16:33.014343270 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4357 "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Successfully stoppedmodule blobstorageiotedge
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Stopping listener for module blobstorageiotedge
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [mgmt] - - - [2021-09-14 17:16:33.014451014 UTC] "POST /modules/blobstorageiotedge/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Successfully stoppedmodule EdaApp
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Stopping listener for module EdaApp
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [mgmt] - - - [2021-09-14 17:16:33.059351872 UTC] "POST /modules/EdaApp/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Successfully stoppedmodule EdaCacher
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - Stopping listener for module EdaCacher
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [mgmt] - - - [2021-09-14 17:16:33.108480555 UTC] "POST /modules/EdaCacher/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [work] - - - [2021-09-14 17:16:33.420402342 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4332 "-" "-" auth_id(-)
Sep 14 17:16:33 iotedge01 iotedged[11743]: 2021-09-14T17:16:33Z [INFO] - [work] - - - [2021-09-14 17:16:33.619782262 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4497 "-" "-" auth_id(-)
Sep 14 17:16:34 iotedge01 iotedged[11743]: 2021-09-14T17:16:34Z [INFO] - [work] - - - [2021-09-14 17:16:34.110735746 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4472 "-" "-" auth_id(-)
Sep 14 17:16:34 iotedge01 iotedged[11743]: 2021-09-14T17:16:34Z [INFO] - [work] - - - [2021-09-14 17:16:34.312100154 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4501 "-" "-" auth_id(-)
Sep 14 17:16:34 iotedge01 iotedged[11743]: 2021-09-14T17:16:34Z [INFO] - [work] - - - [2021-09-14 17:16:34.713339912 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4476 "-" "-" auth_id(-)
Sep 14 17:16:34 iotedge01 iotedged[11743]: 2021-09-14T17:16:34Z [INFO] - [work] - - - [2021-09-14 17:16:34.914801534 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4641 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.215340928 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4616 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.236037516 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4645 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.255736516 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4620 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.280416286 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4793 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.404714516 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4768 "-" "-" auth_id(-)
Sep 14 17:16:35 iotedge01 iotedged[11743]: 2021-09-14T17:16:35Z [INFO] - [work] - - - [2021-09-14 17:16:35.605711420 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4873 "-" "-" auth_id(-)
Sep 14 17:16:36 iotedge01 iotedged[11743]: 2021-09-14T17:16:36Z [INFO] - [work] - - - [2021-09-14 17:16:36.006205941 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4848 "-" "-" auth_id(-)
Sep 14 17:16:36 iotedge01 iotedged[11743]: 2021-09-14T17:16:36Z [INFO] - [work] - - - [2021-09-14 17:16:36.207602287 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 5009 "-" "-" auth_id(-)
Sep 14 17:16:36 iotedge01 iotedged[11743]: 2021-09-14T17:16:36Z [INFO] - [work] - - - [2021-09-14 17:16:36.977176647 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4988 "-" "-" auth_id(-)
Sep 14 17:16:36 iotedge01 iotedged[11743]: 2021-09-14T17:16:36Z [INFO] - [work] - - - [2021-09-14 17:16:36.996790155 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4988 "-" "-" auth_id(-)
Sep 14 17:16:37 iotedge01 iotedged[11743]: 2021-09-14T17:16:37Z [INFO] - [work] - - - [2021-09-14 17:16:37.211084179 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4988 "-" "-" auth_id(-)
Sep 14 17:16:37 iotedge01 iotedged[11743]: 2021-09-14T17:16:37Z [INFO] - [work] - - - [2021-09-14 17:16:37.231337069 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/encrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4129 "-" "-" auth_id(-)
Sep 14 17:16:37 iotedge01 iotedged[11743]: 2021-09-14T17:16:37Z [INFO] - [work] - - - [2021-09-14 17:16:37.251485475 UTC] "POST /modules/%24edgeHub/genid/637587737527741469/decrypt?api-version=2019-01-30 HTTP/1.1" 200 OK 4104 "-" "-" auth_id(-)
Sep 14 17:16:40 iotedge01 iotedged[11743]: 2021-09-14T17:16:40Z [INFO] - Stopping listener for module edgeHub
Sep 14 17:16:40 iotedge01 iotedged[11743]: 2021-09-14T17:16:40Z [INFO] - Successfully stoppedmodule edgeHub
Sep 14 17:16:40 iotedge01 iotedged[11743]: 2021-09-14T17:16:40Z [INFO] - [mgmt] - - - [2021-09-14 17:16:40.437841906 UTC] "POST /modules/edgeHub/stop?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:40 iotedge01 iotedged[11743]: 2021-09-14T17:16:40Z [ERR!] - server connection error: (unknown)
Sep 14 17:16:40 iotedge01 iotedged[11743]: 2021-09-14T17:16:40Z [ERR!] - error writing a body to connection: Broken pipe (os error 32)
Sep 14 17:16:41 iotedge01 iotedged[11743]: 2021-09-14T17:16:41Z [INFO] - Successfully restarted module edgeAgent
Sep 14 17:16:41 iotedge01 iotedged[11743]: 2021-09-14T17:16:41Z [INFO] - [mgmt] - - - [2021-09-14 17:16:41.286988774 UTC] "POST /modules/edgeAgent/restart?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "iotedge/0.1.0" auth_id(-)
Sep 14 17:16:41 iotedge01 iotedged[11743]: 2021-09-14T17:16:41Z [INFO] - [work] - - - [2021-09-14 17:16:41.768515494 UTC] "GET /trust-bundle?api-version=2019-01-30 HTTP/1.1" 200 OK 2314 "-" "-" auth_id(-)
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - Querying system info...
Sep 14 17:16:42 iotedge01 iotedged[11743]: vmware
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - Successfully queried system info
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - [mgmt] - - - [2021-09-14 17:16:42.076135843 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 323 "-" "-" auth_id(-)
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - Querying system info...
Sep 14 17:16:42 iotedge01 iotedged[11743]: vmware
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - Successfully queried system info
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - [mgmt] - - - [2021-09-14 17:16:42.653550326 UTC] "GET /systeminfo?api-version=2020-07-07 HTTP/1.1" 200 OK 323 "-" "-" auth_id(-)
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - [work] - - - [2021-09-14 17:16:42.717304528 UTC] "POST /modules/%24edgeAgent/genid/637587737527741469/decrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 7900 "-" "-" auth_id(-)
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - [work] - - - [2021-09-14 17:16:42.828301789 UTC] "POST /modules/%24edgeAgent/genid/637587737527741469/sign?api-version=2018-06-28 HTTP/1.1" 200 OK 57 "-" "-" auth_id(-)
Sep 14 17:16:42 iotedge01 iotedged[11743]: 2021-09-14T17:16:42Z [INFO] - [mgmt] - - - [2021-09-14 17:16:42.890529043 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10901 "-" "-" auth_id(-)
Sep 14 17:16:43 iotedge01 iotedged[11743]: 2021-09-14T17:16:43Z [INFO] - [work] - - - [2021-09-14 17:16:43.552301617 UTC] "POST /modules/%24edgeAgent/genid/637587737527741469/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 7925 "-" "-" auth_id(-)
Sep 14 17:16:46 iotedge01 iotedged[11743]: 2021-09-14T17:16:46Z [INFO] - Checking edge runtime status
Sep 14 17:16:46 iotedge01 iotedged[11743]: 2021-09-14T17:16:46Z [INFO] - Edge runtime is running.
Sep 14 17:16:48 iotedge01 iotedged[11743]: 2021-09-14T17:16:48Z [INFO] - [mgmt] - - - [2021-09-14 17:16:48.935778095 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10901 "-" "-" auth_id(-)
Sep 14 17:16:53 iotedge01 iotedged[11743]: 2021-09-14T17:16:53Z [INFO] - [mgmt] - - - [2021-09-14 17:16:53.965066851 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10901 "-" "-" auth_id(-)
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - Stopping module mongodb...
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [WARN] - Could not stop module mongodb
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [WARN] - caused by: Target of operation already in this state
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - [mgmt] - - - [2021-09-14 17:16:54.044832055 UTC] "POST /modules/mongodb/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - Starting module mongodb...
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - Successfully started module mongodb
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - [mgmt] - - - [2021-09-14 17:16:54.762455882 UTC] "POST /modules/mongodb/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - Stopping module redisiotedge...
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [WARN] - Could not stop module redisiotedge
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [WARN] - caused by: Target of operation already in this state
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - [mgmt] - - - [2021-09-14 17:16:54.775461607 UTC] "POST /modules/redisiotedge/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
Sep 14 17:16:54 iotedge01 iotedged[11743]: 2021-09-14T17:16:54Z [INFO] - Starting module redisiotedge...
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [INFO] - Successfully started module redisiotedge
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [INFO] - [mgmt] - - - [2021-09-14 17:16:55.510818271 UTC] "POST /modules/redisiotedge/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [INFO] - Stopping module EdaApp...
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [WARN] - Could not stop module EdaApp
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [WARN] - caused by: Target of operation already in this state
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [INFO] - [mgmt] - - - [2021-09-14 17:16:55.515397637 UTC] "POST /modules/EdaApp/stop?api-version=2020-07-07 HTTP/1.1" 304 Not Modified 0 "-" "-" auth_id(-)
Sep 14 17:16:55 iotedge01 iotedged[11743]: 2021-09-14T17:16:55Z [INFO] - Starting module EdaApp...
Sep 14 17:16:56 iotedge01 iotedged[11743]: 2021-09-14T17:16:56Z [INFO] - Successfully started module EdaApp
Sep 14 17:16:56 iotedge01 iotedged[11743]: 2021-09-14T17:16:56Z [INFO] - [mgmt] - - - [2021-09-14 17:16:56.277070548 UTC] "POST /modules/EdaApp/start?api-version=2020-07-07 HTTP/1.1" 204 No Content - "-" "-" auth_id(-)
Sep 14 17:16:56 iotedge01 iotedged[11743]: 2021-09-14T17:16:56Z [INFO] - [work] - - - [2021-09-14 17:16:56.300905334 UTC] "POST /modules/%24edgeAgent/genid/637587737527741469/encrypt?api-version=2020-07-07 HTTP/1.1" 200 OK 7925 "-" "-" auth_id(-)
Sep 14 17:17:01 iotedge01 iotedged[11743]: 2021-09-14T17:17:01Z [INFO] - [mgmt] - - - [2021-09-14 17:17:01.316207223 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:06 iotedge01 iotedged[11743]: 2021-09-14T17:17:06Z [INFO] - [mgmt] - - - [2021-09-14 17:17:06.550828156 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:11 iotedge01 iotedged[11743]: 2021-09-14T17:17:11Z [INFO] - [mgmt] - - - [2021-09-14 17:17:11.571702073 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:16 iotedge01 iotedged[11743]: 2021-09-14T17:17:16Z [INFO] - [mgmt] - - - [2021-09-14 17:17:16.610140309 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:21 iotedge01 iotedged[11743]: 2021-09-14T17:17:21Z [INFO] - [mgmt] - - - [2021-09-14 17:17:21.633339045 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:26 iotedge01 iotedged[11743]: 2021-09-14T17:17:26Z [INFO] - [mgmt] - - - [2021-09-14 17:17:26.649326489 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:31 iotedge01 iotedged[11743]: 2021-09-14T17:17:31Z [INFO] - [mgmt] - - - [2021-09-14 17:17:31.668839700 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
Sep 14 17:17:36 iotedge01 iotedged[11743]: 2021-09-14T17:17:36Z [INFO] - [mgmt] - - - [2021-09-14 17:17:36.686898429 UTC] "GET /modules?api-version=2020-07-07 HTTP/1.1" 200 OK 10904 "-" "-" auth_id(-)
edge-agent logs
2021-09-14 17:16:41 Starting Edge Agent
2021-09-14 17:16:41 Changing ownership of storage folder: /iotedge/storage/edgeAgent to 1000
2021-09-14 17:16:41 Changing ownership of management socket: /var/run/iotedge/mgmt.sock
2021-09-14 17:16:41.343 +00:00 Edge Agent Main()
<6> 2021-09-14 17:16:41.532 +00:00 [INF] - Initializing Edge Agent.
<6> 2021-09-14 17:16:41.679 +00:00 [INF] - Version - 1.1.5.46127017 (7681cae0e56a036f9659814ad559237f88d96fa3)
<6> 2021-09-14 17:16:41.680 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝
██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝
<6> 2021-09-14 17:16:41.720 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2021-09-14 17:16:41.819 +00:00 [INF] - Installing certificates [E=enterpriseadmin@morantug.com, CN=Moran IoT Root CA, OU=IT Department, O=Moran Towing Corporation, L=New Canaan, S=CT, C=US:02/13/2040 03:26:26] to Root
<6> 2021-09-14 17:16:41.926 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: /metrics
<6> 2021-09-14 17:16:42.045 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2021-09-14 17:16:42.049 +00:00 [INF] - Started operation Get system resources
<6> 2021-09-14 17:16:42.050 +00:00 [INF] - Collecting metadata metrics
<6> 2021-09-14 17:16:42.117 +00:00 [INF] - Set metadata metrics: 1.1.5.46127017 (7681cae0e56a036f9659814ad559237f88d96fa3), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"x86_64","Version":"1.1.6","Provisioning":{"Type":"manual.device_connection_string","DynamicReprovisioning":false},"ServerVersion":"20.10.8+azure","KernelVersion":"4.15.0-156-generic","OperatingSystem":"Ubuntu 18.04.6 LTS","NumCpus":12,"Virtualized":"yes"}, True
<6> 2021-09-14 17:16:42.136 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2021-09-14 17:16:42.139 +00:00 [INF] - Started operation refresh twin config
<6> 2021-09-14 17:16:42.155 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...
<6> 2021-09-14 17:16:42.431 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeAgent
<6> 2021-09-14 17:16:42.464 +00:00 [INF] - Started operation Metrics Scrape
<6> 2021-09-14 17:16:42.464 +00:00 [INF] - Started operation Metrics Upload
Scraping frequency: 01:00:00
Upload Frequency: 1.00:00:00
<6> 2021-09-14 17:16:42.663 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2021-09-14 17:16:42.663 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2021-09-14 17:16:42.663 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2021-09-14 17:16:42.663 +00:00 [INF] - Registering request handler RestartModule
<6> 2021-09-14 17:16:43.179 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_Tcp_Only.
<6> 2021-09-14 17:16:43.351 +00:00 [INF] - Initialized new module client with subscriptions enabled
<6> 2021-09-14 17:16:43.487 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 238 and reported properties version 2991.
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'mongodb' scheduled to restart after 20s (06s left).
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.671 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.672 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (01m:16s left).
<6> 2021-09-14 17:16:43.672 +00:00 [INF] - Module 'redisiotedge' scheduled to restart after 20s (06s left).
<6> 2021-09-14 17:16:43.672 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:43.672 +00:00 [INF] - Module 'EdaApp' scheduled to restart after 20s (06s left).
<6> 2021-09-14 17:16:43.923 +00:00 [INF] - Updated reported properties
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'mongodb' scheduled to restart after 20s (01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (01m:11s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'redisiotedge' scheduled to restart after 20s (01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (01m:01s left).
<6> 2021-09-14 17:16:48.949 +00:00 [INF] - Module 'EdaApp' scheduled to restart after 20s (01s left).
<6> 2021-09-14 17:16:53.996 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:53.997 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:53.997 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:54.018 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:54.018 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:54.018 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (01m:06s left).
<6> 2021-09-14 17:16:54.018 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (56s left).
<6> 2021-09-14 17:16:54.025 +00:00 [INF] - Plan execution started for deployment 238
<6> 2021-09-14 17:16:54.028 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module mongodb]\n [Start module mongodb]\n [Saving mongodb to store]\n)"
<6> 2021-09-14 17:16:54.032 +00:00 [INF] - Executing command: "Stop module mongodb"
<6> 2021-09-14 17:16:54.057 +00:00 [INF] - Executing command: "Start module mongodb"
<6> 2021-09-14 17:16:54.764 +00:00 [INF] - Executing command: "Saving mongodb to store"
<6> 2021-09-14 17:16:54.774 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module redisiotedge]\n [Start module redisiotedge]\n [Saving redisiotedge to store]\n)"
<6> 2021-09-14 17:16:54.774 +00:00 [INF] - Executing command: "Stop module redisiotedge"
<6> 2021-09-14 17:16:54.777 +00:00 [INF] - Executing command: "Start module redisiotedge"
<6> 2021-09-14 17:16:55.512 +00:00 [INF] - Executing command: "Saving redisiotedge to store"
<6> 2021-09-14 17:16:55.513 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module EdaApp]\n [Start module EdaApp]\n [Saving EdaApp to store]\n)"
<6> 2021-09-14 17:16:55.513 +00:00 [INF] - Executing command: "Stop module EdaApp"
<6> 2021-09-14 17:16:55.517 +00:00 [INF] - Executing command: "Start module EdaApp"
<6> 2021-09-14 17:16:56.277 +00:00 [INF] - Executing command: "Saving EdaApp to store"
<6> 2021-09-14 17:16:56.278 +00:00 [INF] - Plan execution ended for deployment 238
<6> 2021-09-14 17:17:01.332 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:01.332 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (49s left).
<6> 2021-09-14 17:17:01.333 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:01.333 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:01.333 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:01.333 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (58s left).
<6> 2021-09-14 17:17:01.333 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:01.542 +00:00 [INF] - Updated reported properties
<6> 2021-09-14 17:17:06.560 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (44s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (53s left).
<6> 2021-09-14 17:17:06.561 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:11.590 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (39s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (48s left).
<6> 2021-09-14 17:17:11.591 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:16.622 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:16.622 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (34s left).
<6> 2021-09-14 17:17:16.622 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:16.622 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:16.622 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:16.623 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (43s left).
<6> 2021-09-14 17:17:16.623 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (29s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (38s left).
<6> 2021-09-14 17:17:21.640 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (33s left).
<6> 2021-09-14 17:17:26.656 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (28s left).
<6> 2021-09-14 17:17:31.677 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (23s left).
<6> 2021-09-14 17:17:36.703 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:41.722 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:41.722 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:41.722 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:41.722 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:41.722 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:41.723 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (18s left).
<6> 2021-09-14 17:17:41.723 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (13s left).
<6> 2021-09-14 17:17:46.761 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 01m:20s (03s left).
<6> 2021-09-14 17:17:51.792 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 01m:20s (08s left).
<6> 2021-09-14 17:17:51.793 +00:00 [INF] - Plan execution started for deployment 238
<6> 2021-09-14 17:17:51.793 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module MetaAnalyzer]\n [Start module MetaAnalyzer]\n [Saving MetaAnalyzer to store]\n)"
<6> 2021-09-14 17:17:51.793 +00:00 [INF] - Executing command: "Stop module MetaAnalyzer"
<6> 2021-09-14 17:17:51.795 +00:00 [INF] - Executing command: "Start module MetaAnalyzer"
<6> 2021-09-14 17:17:52.657 +00:00 [INF] - Executing command: "Saving MetaAnalyzer to store"
<6> 2021-09-14 17:17:52.659 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module EdaCacher]\n [Start module EdaCacher]\n [Saving EdaCacher to store]\n)"
<6> 2021-09-14 17:17:52.659 +00:00 [INF] - Executing command: "Stop module EdaCacher"
<6> 2021-09-14 17:17:52.662 +00:00 [INF] - Executing command: "Start module EdaCacher"
<6> 2021-09-14 17:17:53.424 +00:00 [INF] - Executing command: "Saving EdaCacher to store"
<6> 2021-09-14 17:17:53.424 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module blobstorageiotedge]\n [Start module blobstorageiotedge]\n [Saving blobstorageiotedge to store]\n)"
<6> 2021-09-14 17:17:53.424 +00:00 [INF] - Executing command: "Stop module blobstorageiotedge"
<6> 2021-09-14 17:17:53.426 +00:00 [INF] - Executing command: "Start module blobstorageiotedge"
<6> 2021-09-14 17:17:54.211 +00:00 [INF] - Executing command: "Saving blobstorageiotedge to store"
<6> 2021-09-14 17:17:54.212 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module AnomalyChecker]\n [Start module AnomalyChecker]\n [Saving AnomalyChecker to store]\n)"
<6> 2021-09-14 17:17:54.212 +00:00 [INF] - Executing command: "Stop module AnomalyChecker"
<6> 2021-09-14 17:17:54.214 +00:00 [INF] - Executing command: "Start module AnomalyChecker"
<6> 2021-09-14 17:17:54.965 +00:00 [INF] - Executing command: "Saving AnomalyChecker to store"
<6> 2021-09-14 17:17:54.966 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module MessageLogger]\n [Start module MessageLogger]\n [Saving MessageLogger to store]\n)"
<6> 2021-09-14 17:17:54.966 +00:00 [INF] - Executing command: "Stop module MessageLogger"
<6> 2021-09-14 17:17:54.968 +00:00 [INF] - Executing command: "Start module MessageLogger"
<6> 2021-09-14 17:17:55.820 +00:00 [INF] - Executing command: "Saving MessageLogger to store"
<6> 2021-09-14 17:17:55.820 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module WindowMerger]\n [Start module WindowMerger]\n [Saving WindowMerger to store]\n)"
<6> 2021-09-14 17:17:55.820 +00:00 [INF] - Executing command: "Stop module WindowMerger"
<6> 2021-09-14 17:17:55.822 +00:00 [INF] - Executing command: "Start module WindowMerger"
<6> 2021-09-14 17:17:56.577 +00:00 [INF] - Executing command: "Saving WindowMerger to store"
<6> 2021-09-14 17:17:56.578 +00:00 [INF] - Plan execution ended for deployment 238
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 02m:40s (02m:31s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 02m:40s (02m:32s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 02m:40s (02m:32s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 02m:40s (02m:33s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 02m:40s (02m:34s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 02m:40s (02m:35s left).
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Plan execution started for deployment 238
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module edgeHub]\n [Start module edgeHub]\n [Saving edgeHub to store]\n)"
<6> 2021-09-14 17:18:01.634 +00:00 [INF] - Executing command: "Stop module edgeHub"
<6> 2021-09-14 17:18:01.636 +00:00 [INF] - Executing command: "Start module edgeHub"
<6> 2021-09-14 17:18:02.366 +00:00 [INF] - Executing command: "Saving edgeHub to store"
<6> 2021-09-14 17:18:02.366 +00:00 [INF] - Plan execution ended for deployment 238
<6> 2021-09-14 17:18:02.599 +00:00 [INF] - Updated reported properties
<6> 2021-09-14 17:18:07.612 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 02m:40s (02m:25s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 02m:40s (02m:26s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 02m:40s (02m:26s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 02m:40s (02m:27s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 02m:40s (02m:28s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 02m:40s (02m:35s left).
<6> 2021-09-14 17:18:07.613 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 02m:40s (02m:29s left).
<6> 2021-09-14 17:18:07.815 +00:00 [INF] - Updated reported properties
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 02m:40s (02m:20s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 02m:40s (02m:20s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 02m:40s (02m:21s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 02m:40s (02m:22s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 02m:40s (02m:23s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 02m:40s (02m:30s left).
<6> 2021-09-14 17:18:12.830 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 02m:40s (02m:24s left).
<6> 2021-09-14 17:18:17.853 +00:00 [INF] - Module 'MetaAnalyzer' scheduled to restart after 02m:40s (02m:15s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'EdaCacher' scheduled to restart after 02m:40s (02m:15s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'blobstorageiotedge' scheduled to restart after 02m:40s (02m:16s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'AnomalyChecker' scheduled to restart after 02m:40s (02m:17s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'MessageLogger' scheduled to restart after 02m:40s (02m:18s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'edgeHub' scheduled to restart after 02m:40s (02m:25s left).
<6> 2021-09-14 17:18:17.854 +00:00 [INF] - Module 'WindowMerger' scheduled to restart after 02m:40s (02m:19s left).
edge-hub logs
<6> 2021-09-14 17:16:30.038 +00:00 [INF] - Termination requested, initiating shutdown.
<6> 2021-09-14 17:16:30.039 +00:00 [INF] - Stopping the protocol heads...
<6> 2021-09-14 17:16:30.039 +00:00 [INF] - Closing protocol heads - (MQTT, AMQP, HTTP)
<6> 2021-09-14 17:16:30.040 +00:00 [INF] - Stopping
<6> 2021-09-14 17:16:30.052 +00:00 [INF] - Closing connection for device: MTC01/EdaCacher, ,
<6> 2021-09-14 17:16:30.052 +00:00 [INF] - Closing connection for device: MTC01/AnomalyChecker, ,
<6> 2021-09-14 17:16:30.053 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/AnomalyChecker because of exception -
<6> 2021-09-14 17:16:30.053 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/EdaCacher because of exception -
<6> 2021-09-14 17:16:30.053 +00:00 [INF] - Closing HTTP head
<6> 2021-09-14 17:16:30.054 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/EdaCacher
<6> 2021-09-14 17:16:30.054 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/AnomalyChecker
<6> 2021-09-14 17:16:30.056 +00:00 [INF] - Removing device connection for device MTC01/EdaCacher with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.056 +00:00 [INF] - Removing device connection for device MTC01/AnomalyChecker with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.057 +00:00 [INF] - Waiting for cleanup to finish
<6> 2021-09-14 17:16:30.068 +00:00 [INF] - Closing connection for device: MTC01/MetaAnalyzer, ,
<6> 2021-09-14 17:16:30.069 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/MetaAnalyzer because of exception -
<6> 2021-09-14 17:16:30.069 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/MetaAnalyzer
<6> 2021-09-14 17:16:30.069 +00:00 [INF] - Removing device connection for device MTC01/MetaAnalyzer with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.079 +00:00 [INF] - Closing receiver in cloud proxy 82c269fc-460a-41cb-92c1-f6f1bb3723e8 for MTC01/EdaCacher
<6> 2021-09-14 17:16:30.079 +00:00 [INF] - Closed cloud proxy 82c269fc-460a-41cb-92c1-f6f1bb3723e8 for MTC01/EdaCacher
<6> 2021-09-14 17:16:30.080 +00:00 [INF] - Device connection removed for device MTC01/EdaCacher
<6> 2021-09-14 17:16:30.080 +00:00 [INF] - Closing receiver in cloud proxy 745ff04b-b6e5-46ef-bd8c-1498a37e8a31 for MTC01/AnomalyChecker
<6> 2021-09-14 17:16:30.080 +00:00 [INF] - Closed cloud proxy 745ff04b-b6e5-46ef-bd8c-1498a37e8a31 for MTC01/AnomalyChecker
<6> 2021-09-14 17:16:30.080 +00:00 [INF] - Device connection removed for device MTC01/AnomalyChecker
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Closing connection for device: MTC01/MessageLogger, ,
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/MessageLogger because of exception -
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Closing receiver in cloud proxy b7bce080-cfbf-4a53-a91a-a07f16e0041a for MTC01/MetaAnalyzer
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/MessageLogger
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Closed cloud proxy b7bce080-cfbf-4a53-a91a-a07f16e0041a for MTC01/MetaAnalyzer
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Removing device connection for device MTC01/MessageLogger with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Device connection removed for device MTC01/MetaAnalyzer
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Closing receiver in cloud proxy 547909f6-9ad9-423e-9a91-dd85774b29c6 for MTC01/MessageLogger
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Closed cloud proxy 547909f6-9ad9-423e-9a91-dd85774b29c6 for MTC01/MessageLogger
<6> 2021-09-14 17:16:30.081 +00:00 [INF] - Device connection removed for device MTC01/MessageLogger
<6> 2021-09-14 17:16:30.082 +00:00 [INF] - Remove device connection for device MTC01/EdaCacher
<6> 2021-09-14 17:16:30.082 +00:00 [INF] - Remove device connection for device MTC01/MessageLogger
<6> 2021-09-14 17:16:30.082 +00:00 [INF] - Remove device connection for device MTC01/AnomalyChecker
<6> 2021-09-14 17:16:30.082 +00:00 [INF] - Remove device connection for device MTC01/MetaAnalyzer
<4> 2021-09-14 17:16:30.096 +00:00 [WRN] - Failed to release a message: PublishPacket[Type=PUBLISH, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]
DotNetty.Common.Utilities.IllegalReferenceCountException: refCnt: 0, decrement: 1
at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release0(Int32 decrement)
at DotNetty.Common.Utilities.ReferenceCountUtil.SafeRelease(IReferenceCounted msg)
<4> 2021-09-14 17:16:30.157 +00:00 [WRN] - Error reading transport. CorrelationId 7d87fa0c
System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
---> System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
at System.Net.WebSockets.ManagedWebSocket.ThrowIfEOFUnexpected(Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 222
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 133
<6> 2021-09-14 17:16:30.164 +00:00 [INF] - Transport aborted. CorrelationId 7d87fa0c
<4> 2021-09-14 17:16:30.167 +00:00 [WRN] - Closing connection for device: MTC01/blobstorageiotedge, scope: ExceptionCaught, System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
---> System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
at System.Net.WebSockets.ManagedWebSocket.ThrowIfEOFUnexpected(Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 222
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 133, 7d87fa0c
<6> 2021-09-14 17:16:30.168 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/blobstorageiotedge because of exception - System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
---> System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake.
at System.Net.WebSockets.ManagedWebSocket.ThrowIfEOFUnexpected(Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.EnsureBufferContainsAsync(Int32 minimumRequiredBytes, CancellationToken cancellationToken, Boolean throwOnPrematureClosure)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at System.Net.WebSockets.ManagedWebSocket.ReceiveAsyncPrivate[TWebSocketReceiveResultGetter,TWebSocketReceiveResult](Memory`1 payloadBuffer, CancellationToken cancellationToken, TWebSocketReceiveResultGetter resultGetter)
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoReadBytes(IByteBuffer byteBuffer) in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 222
at Microsoft.Azure.Devices.Edge.Hub.Mqtt.ServerWebSocketChannel.DoBeginRead() in /home/vsts/work/1/s/edge-hub/src/Microsoft.Azure.Devices.Edge.Hub.Mqtt/ServerWebSocketChannel.cs:line 133
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/blobstorageiotedge
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Removing device connection for device MTC01/blobstorageiotedge with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Request finished in 423909.0847ms 101
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Closing receiver in cloud proxy c3936a53-231d-4858-9145-559d00e052b2 for MTC01/blobstorageiotedge
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Closed cloud proxy c3936a53-231d-4858-9145-559d00e052b2 for MTC01/blobstorageiotedge
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Device connection removed for device MTC01/blobstorageiotedge
<6> 2021-09-14 17:16:30.169 +00:00 [INF] - Remove device connection for device MTC01/blobstorageiotedge
<6> 2021-09-14 17:16:30.171 +00:00 [INF] - Transport closed. CorrelationId 7d87fa0c
<6> 2021-09-14 17:16:30.182 +00:00 [INF] - Closed HTTP head
<4> 2021-09-14 17:16:30.380 +00:00 [WRN] - Closing connection for device: MTC01/WindowMerger, scope: ExceptionCaught, System.Net.Sockets.SocketException (104): Connection reset by peer
at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoReadBytes(IByteBuffer byteBuf)
at DotNetty.Transport.Channels.Sockets.AbstractSocketByteChannel.SocketByteChannelUnsafe.FinishRead(SocketChannelAsyncOperation operation), 759d3f26
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Disposing MessagingServiceClient for device Id MTC01/WindowMerger because of exception - System.Net.Sockets.SocketException (104): Connection reset by peer
at DotNetty.Transport.Channels.Sockets.TcpSocketChannel.DoReadBytes(IByteBuffer byteBuf)
at DotNetty.Transport.Channels.Sockets.AbstractSocketByteChannel.SocketByteChannelUnsafe.FinishRead(SocketChannelAsyncOperation operation)
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Setting device proxy inactive for device Id MTC01/WindowMerger
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Removing device connection for device MTC01/WindowMerger with removeCloudConnection flag 'True'.
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Closing receiver in cloud proxy 63346f6e-018f-4f26-98ee-a793a2e0ae89 for MTC01/WindowMerger
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Closed cloud proxy 63346f6e-018f-4f26-98ee-a793a2e0ae89 for MTC01/WindowMerger
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Device connection removed for device MTC01/WindowMerger
<6> 2021-09-14 17:16:30.380 +00:00 [INF] - Remove device connection for device MTC01/WindowMerger
<6> 2021-09-14 17:16:31.419 +00:00 [INF] - Updated reported properties for MTC01/$edgeHub
<6> 2021-09-14 17:16:37.191 +00:00 [INF] - Updated reported properties for MTC01/$edgeHub
2021-09-14 17:18:02 Starting Edge Hub
2021-09-14 17:18:02.413 +00:00 Edge Hub Main()
<3> 2021-09-14 17:18:02.783 +00:00 [ERR] - Shutting down because no response from unix:///var/run/iotedge/workload.sock for CreateServerCertificateAsync
System.Net.Internals.SocketExceptionFactory+ExtendedSocketException (111): Connection refused /var/run/iotedge/workload.sock
at System.Net.Sockets.Socket.DoConnect(EndPoint endPointSnapshot, SocketAddress socketAddress)
at System.Net.Sockets.Socket.Connect(EndPoint remoteEP)
at System.Net.Sockets.Socket.UnsafeBeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state, Boolean flowContext)
at System.Net.Sockets.Socket.BeginConnect(EndPoint remoteEP, AsyncCallback callback, Object state)
at System.Net.Sockets.Socket.ConnectAsync(EndPoint remoteEP)
at System.Net.Sockets.SocketTaskExtensions.ConnectAsync(Socket socket, EndPoint remoteEP)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.GetConnectedSocketAsync() in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 47
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 23
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Util.Edged.Version_2019_01_30.GeneratedCode.HttpWorkloadClient.CreateServerCertificateAsync(String api_version, String name, String genid, ServerCertificateRequest request, CancellationToken cancellationToken) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/version_2019_01_30/generatedCode/HttpWorkloadClient.cs:line 594
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 126
at Microsoft.Azure.Devices.Edge.Util.Edged.WorkloadClientVersioned.Execute[T](Func`1 func, String operation) in /home/vsts/work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/edged/WorkloadClientVersioned.cs:line 59
Additional Information
Because it seems relevant, here is the output of ls -alh /var/run/iotedge
:
drwxr-xr-x 2 root root 80 Sep 14 17:08 .
drwxr-xr-x 30 root root 1.1K Sep 14 17:09 ..
srw-rw---- 1 iotadmin iotedge 0 Sep 14 17:08 mgmt.sock
srw-rw-rw- 1 iotedge iotedge 0 Sep 14 17:08 workload.sock
About this issue
- Original URL
- State: closed
- Created 3 years ago
- Comments: 44 (17 by maintainers)
I think the issue is due to a change introduced in 1.1.6. In 1.1.6, a workload socket with a listen on the socket is created when each module is created. The listener is stopped when the module is stopped. However, if the module is simply started again and not “created” then the listener is not created either. This situation would happen when updating edgeAgent. EdgeAgent would stop edgeHub (this would stop the listener) and restart edgeHub (listener not created again). This will need a fix. In the meantime, here are some work arounds:
FYI I have tested downgrading and this issue is not reproducible after downgrading
iotedged
to1.1.5
. Furthermore, on version1.1.6
ofiotedged
asudo systemctl restart iotedge
temporarily mitigated the issue. Both of these clues suggest the issue is from 1.1.6 of iotedged.we also have this problem in aziot-edged 1.4.2, aziot-edged-identity 1.4.1, edgeAgent 1.2.8, edgeHub 1.2.8
1.1.8 release went out yesterday and we believe that should take of any remaining issues related to Workload socket that we’re aware of.
Closing this issue, please reopen if your tests with 1.1.8 show any related problems.
Hi @ggjjj here’s another reproduction of the issue (
iotedged=1.1.6
) with debug logs turned on for the daemon. I issuediotedge restart edgeAgent
right around2021-09-17 14:44:00
. Please let me know if there’s anything else you need from me.aziot-edged logs
Github gist containing logs
edge-agent logs
edge-hub logs