Closed jackt-moran closed 2 years ago
In case it is helpful, I have some additional info.
Most of our devices have been deployed and working without issue for over 6 months, some of them were running iotedge 1.0.x for some time, and all of them have generally been updated on a weekly basis. We have not had stability issues such as I described above until the past 6 weeks or so.
Although until recently everything worked well, I figured I'd go ahead and verify that my Linux Kernels are compatible with moby, so I went ahead and ran the script from here:
warning: /proc/config.gz does not exist, searching other paths for kernel config ...
info: reading kernel config from /boot/config-4.15.0-156-generic ...
Generally Necessary:
- cgroup hierarchy: properly mounted [/sys/fs/cgroup]
- apparmor: enabled and tools installed
- CONFIG_NAMESPACES: enabled
- CONFIG_NET_NS: enabled
- CONFIG_PID_NS: enabled
- CONFIG_IPC_NS: enabled
- CONFIG_UTS_NS: enabled
- CONFIG_CGROUPS: enabled
- CONFIG_CGROUP_CPUACCT: enabled
- CONFIG_CGROUP_DEVICE: enabled
- CONFIG_CGROUP_FREEZER: enabled
- CONFIG_CGROUP_SCHED: enabled
- CONFIG_CPUSETS: enabled
- CONFIG_MEMCG: enabled
- CONFIG_KEYS: enabled
- CONFIG_VETH: enabled (as module)
- CONFIG_BRIDGE: enabled (as module)
- CONFIG_BRIDGE_NETFILTER: enabled (as module)
- CONFIG_IP_NF_FILTER: enabled (as module)
- CONFIG_IP_NF_TARGET_MASQUERADE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_ADDRTYPE: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_CONNTRACK: enabled (as module)
- CONFIG_NETFILTER_XT_MATCH_IPVS: enabled (as module)
- CONFIG_NETFILTER_XT_MARK: enabled (as module)
- CONFIG_IP_NF_NAT: enabled (as module)
- CONFIG_NF_NAT: enabled (as module)
- CONFIG_POSIX_MQUEUE: enabled
- CONFIG_NF_NAT_IPV4: enabled (as module)
- CONFIG_NF_NAT_NEEDED: enabled
- CONFIG_CGROUP_BPF: enabled
Optional Features:
- CONFIG_USER_NS: enabled
- CONFIG_SECCOMP: enabled
- CONFIG_SECCOMP_FILTER: enabled
- CONFIG_CGROUP_PIDS: enabled
- CONFIG_MEMCG_SWAP: enabled
- CONFIG_MEMCG_SWAP_ENABLED: missing
(cgroup swap accounting is currently not enabled, you can enable it by setting boot option "swapaccount=1")
- CONFIG_LEGACY_VSYSCALL_EMULATE: enabled
- CONFIG_IOSCHED_CFQ: enabled
- CONFIG_CFQ_GROUP_IOSCHED: enabled
- CONFIG_BLK_CGROUP: enabled
- CONFIG_BLK_DEV_THROTTLING: enabled
- CONFIG_CGROUP_PERF: enabled
- CONFIG_CGROUP_HUGETLB: enabled
- CONFIG_NET_CLS_CGROUP: enabled (as module)
- CONFIG_CGROUP_NET_PRIO: enabled
- CONFIG_CFS_BANDWIDTH: enabled
- CONFIG_FAIR_GROUP_SCHED: enabled
- CONFIG_RT_GROUP_SCHED: missing
- CONFIG_IP_NF_TARGET_REDIRECT: enabled (as module)
- CONFIG_IP_VS: enabled (as module)
- CONFIG_IP_VS_NFCT: enabled
- CONFIG_IP_VS_PROTO_TCP: enabled
- CONFIG_IP_VS_PROTO_UDP: enabled
- CONFIG_IP_VS_RR: enabled (as module)
- CONFIG_SECURITY_SELINUX: enabled
- CONFIG_SECURITY_APPARMOR: enabled
- CONFIG_EXT4_FS: enabled
- CONFIG_EXT4_FS_POSIX_ACL: enabled
- CONFIG_EXT4_FS_SECURITY: enabled
- Network Drivers:
- "overlay":
- CONFIG_VXLAN: enabled (as module)
- CONFIG_BRIDGE_VLAN_FILTERING: enabled
Optional (for encrypted networks):
- CONFIG_CRYPTO: enabled
- CONFIG_CRYPTO_AEAD: enabled
- CONFIG_CRYPTO_GCM: enabled
- CONFIG_CRYPTO_SEQIV: enabled
- CONFIG_CRYPTO_GHASH: enabled
- CONFIG_XFRM: enabled
- CONFIG_XFRM_USER: enabled (as module)
- CONFIG_XFRM_ALGO: enabled (as module)
- CONFIG_INET_ESP: enabled (as module)
- CONFIG_INET_XFRM_MODE_TRANSPORT: enabled (as module)
- "ipvlan":
- CONFIG_IPVLAN: enabled (as module)
- "macvlan":
- CONFIG_MACVLAN: enabled (as module)
- CONFIG_DUMMY: enabled (as module)
- "ftp,tftp client in container":
- CONFIG_NF_NAT_FTP: enabled (as module)
- CONFIG_NF_CONNTRACK_FTP: enabled (as module)
- CONFIG_NF_NAT_TFTP: enabled (as module)
- CONFIG_NF_CONNTRACK_TFTP: enabled (as module)
- Storage Drivers:
- "aufs":
- CONFIG_AUFS_FS: enabled (as module)
- "btrfs":
- CONFIG_BTRFS_FS: enabled (as module)
- CONFIG_BTRFS_FS_POSIX_ACL: enabled
- "devicemapper":
- CONFIG_BLK_DEV_DM: enabled
- CONFIG_DM_THIN_PROVISIONING: enabled (as module)
- "overlay":
- CONFIG_OVERLAY_FS: enabled (as module)
- "zfs":
- /dev/zfs: missing
- zfs command: missing
- zpool command: missing
Limits:
- /proc/sys/kernel/keys/root_maxkeys: 1000000
Also, given that our entire device fleet is now affected by this issue and it increases the likelihood of data loss, I am going to open an Azure support request and include a link to this issue in that request.
FYI I have tested downgrading and this issue is not reproducible after downgrading iotedged
to 1.1.5
. Furthermore, on version 1.1.6
of iotedged
a sudo systemctl restart iotedge
temporarily mitigated the issue. Both of these clues suggest the issue is from 1.1.6 of iotedged.
Looking into this and will get back to you soon.
Can you enable the debug logs for the aziot-edged ? During the time ( 17:18:02) the edgehub has failed with 111 error, there are no logs available in the edged after 17:17:36 - may be it crashed and its not running. thats why the error shows up. I will try to repro in my end in the mean time. if you can get debug logs please attach them as well. thanks!
@ggjjj since I am on iotedge 1.1.X it seems the system command doesn't exist:
iotadmin@iotedge01:~$ sudo iotedge --help
iotedge 1.1.6
The iotedge tool is used to manage the IoT Edge runtime.
USAGE:
iotedge [OPTIONS] <SUBCOMMAND>
FLAGS:
-h, --help Prints help information
-V, --version Prints version information
OPTIONS:
-H, --host <HOST> Daemon socket to connect to [env: IOTEDGE_HOST=] [default: unix:///var/run/iotedge/mgmt.sock]
SUBCOMMANDS:
check Check for common config and deployment issues
check-list List the checks that are run for 'iotedge check'
help Prints this message or the help of the given subcommand(s)
list List modules
logs Fetch the logs of a module
restart Restart a module
support-bundle Bundles troubleshooting information
version Show the version information
Also, I tried setting RuntimeLogLevel
to debug
in /etc/iotedge/config.yml
which only turned on debug logs for the containers not iotedged. I'm sure I'm missing something here but how can I get the iotedged to output debug logs?
When you can let me know about the above I will get debug level logs for you ASAP.
FYI, after downgrading our fleet of devices to iotedged=1.1.5
we still had some lingering issues (on about 30% of our devices). The errors generally looked related to the issue documented here, but since these are production devices I was focused on recovering from the outage rather than capturing logs. I tested out downgrading further, to iotedged=1.1.4
, and the issue(s) appears to be fully resolved on all of our devices.
Please use this method to enable debug logs : https://docs.microsoft.com/en-us/azure/iot-edge/troubleshoot?view=iotedge-2018-06&preserve-view=true#check-the-status-of-the-iot-edge-security-manager-and-its-logs
Hi @ggjjj here's another reproduction of the issue (iotedged=1.1.6
) with debug logs turned on for the daemon. I issued iotedge restart edgeAgent
right around 2021-09-17 14:44:00
. Please let me know if there's anything else you need from me.
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:
Are there any updates on this issue? The workaround @huguesBouvier shared works in most but not all cases for our set of devices. Exacerbating the issue is that the workaround doesn't work on a non-changing set of devices, so we now have a few devices with 14+ days of data backlogged which we're risking losing forever as time moves forward and the issue persists.
Hello, we are working on releasing the fix, though I can't commit on a specific date. Thank you for your patience!
Understood - thank you for the update!
@jackt-moran 1.1.7 was released a few hours ago with a fix for this issue. Please test this out and let us know if it helps!
@veyalla I had the same problem with 1.1.6, looked into it for some days. My edgeAgent and edgeHub was running, but a custom module was giving this error upon edge runtime startup. I just updated to iotedge 1.1.7 and problem solved! You saved my day (and a night sleep), thanks!
@veyalla that's great news! 1.1.7 has fixed the issue in our staging environment, and I'm phasing the patch out to the rest of our devices. I will update this issue with my findings.
@veyalla I think I still have the problem. I've pushed a new version of our module to a system, and now the edgeHub is complaining with the same error (Permission denied on workload.sock). Tried to reboot, remove iotedge, reboot, reinstall - no solution I reverted to 1.1.5, my edgeHub is now ok, but my module now fails with this workload.sock error. Any idea what could be the reason?
@wvangeem - From what you said below, here is what I gathered -
I reverted to 1.1.5, my edgeHub is now ok, but my module now fails with this workload.sock error.
What components did you revert?
Also, to help us debug further, can you provide us a little more information -
@huguesBouvier fyi.
@wvangeem The error looks different Connections refused (err 111) != Permission denied on workload.sock Could you please provide us with the support bundle? Additionally, could you please do "ls -l /var/lib/aziot/edged/mnt/" on the sock folder and "ls -l /var/lib/aziot/edged/" on its parent so we can check the permissions? Thanks! If the issue is urgent, most likely deleting that mnt folder and restarting IoTedge will solve the issue.
This an unexpected issue, changing/adding a module should not have impact on edgeHub workload.sock permission. If you can't provide the support bundle, could you give the edged logs?
@huguesBouvier I just uninstalled 1.1.5 and reinstalled 1.1.7 and everything seems to work again, also after reboot the system several times.ll My system is Ubuntu 18.04 on arm64. When reverting, I both reverted iotedge to 1.1.5 and libiothsm-std to 1.1.5. When reverting I take following steps: remove both packages, reboot, install again, because when removing, the socket files stay behind, only when rebooting they dissapear. When on 1.1.5 this was the state of the sock files:
Here are the screenshots of the requested folders when back on 1.1.7. I'm still on 1.1, so the folders are iotedge instead of aziot. The subfolder edged is not there in this case.
But the problems start coming up, if I enable the 4G modem on the device, seems the problem is there. I have to look further into it.
Thanks! If the issue happens again, please let us know and tell what you see in that "/var/lib/aziot/edged/mnt" folder (not "/var/run/iotedge.")
@huguesBouvier I've had some issues with the 1.1.7 (although it isn't clear if it is a single issue or multiple). On our staging machine I found a module had failed. Based on the discussion above I inspected /var/lib/iotedge/mnt
and saw something of note:
iotadmin@iotedge01:~$ ls -l /var/lib/iotedge/mnt/
total 0
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 AnomalyChecker.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 blobstorageiotedge.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 BlobStorageManager.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 EdaApp.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 EdaCacher.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 edgeAgent.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 edgeHub.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 MessageLogger.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 MetaAnalyzer.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 mongodb.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 12:02 redisiotedge.sock
srwxr-xr-x 1 iotedge iotedge 0 Oct 15 12:02 WindowMerger.sock
The socket with odd permissions is the one that I found to be failing, and it had a Python stack trace as follows (which I've seen throughout the lifetime of this issue):
Traceback (most recent call last):
File "./windowMerger.py", line 166, in <module>
asyncio.run(main())
File "/usr/local/lib/python3.8/asyncio/runners.py", line 44, in run
return loop.run_until_complete(main)
File "/usr/local/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
return future.result()
File "./windowMerger.py", line 132, in main
module_client = init_module_client()
File "/usr/local/lib/python3.8/site-packages/mtc_iot/iotedge.py", line 28, in init_module_client
return IoTHubModuleClient.create_from_edge_environment()
File "/usr/local/lib/python3.8/site-packages/azure/iot/device/aio/patch_documentation.py", line 224, in create_from_edge_environment
return super(IoTHubModuleClient_, cls).create_from_edge_environment(**kwargs)
File "/usr/local/lib/python3.8/site-packages/azure/iot/device/iothub/abstract_clients.py", line 688, in create_from_edge_environment
server_verification_cert = hsm.get_certificate()
File "/usr/local/lib/python3.8/site-packages/azure/iot/device/iothub/edge_hsm.py", line 62, in get_certificate
r = requests.get(
File "/usr/local/lib/python3.8/site-packages/requests_unixsocket/__init__.py", line 51, in get
return request('get', url, **kwargs)
File "/usr/local/lib/python3.8/site-packages/requests_unixsocket/__init__.py", line 46, in request
return session.request(method=method, url=url, **kwargs)
File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 542, in request
resp = self.send(prep, **send_kwargs)
File "/usr/local/lib/python3.8/site-packages/requests/sessions.py", line 655, in send
r = adapter.send(request, **kwargs)
File "/usr/local/lib/python3.8/site-packages/requests/adapters.py", line 498, in send
raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', PermissionError(13, 'Permission denied'))
In a test, I deleted that socket and ran sudo systemctl restart iotedge
and the module continues to fail. The resulting permissions in /var/lib/iotedge/mnt
afterwards were as follows:
iotadmin@iotedge01:~$ ls -l /var/lib/iotedge/mnt/
total 4
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 AnomalyChecker.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 blobstorageiotedge.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 BlobStorageManager.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 EdaApp.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 EdaCacher.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 edgeAgent.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 edgeHub.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 MessageLogger.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 MetaAnalyzer.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 mongodb.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 15 13:21 redisiotedge.sock
drwxr-xr-x 2 root root 4096 Oct 15 13:20 WindowMerger.sock
Hopefully this gives a clue as to what's going on. I got partially through phasing the update out, after which I noticed issues on patched production devices, so I didn't phase out any further. The production devices are having a different looking issue which I will share below. For all I know it could be 2 different manifestations of the same issue or 2 separate issues.
Below is a sample of the iotedged
logs from one of our production devices experiencing an issue. For context, most of the other devices we have with issues look like this, although I can pull more logs for a bigger sample size if that would be helpful. From a naive perspective, what is happening is post re-install of iotedge the iotedged
is unable to pull down any containers and fails trying to pull edgeAgent indefinitely.
One additional piece of info, in case it provides any clues: every device that has been having issues such as the above 2 cases shows 2 zombie processes when I log on to the machine; however, when I try to find the zombie processes through ps
or htop
I can't find any such processes. Seems related (maybe just a side effect) to the issue.
Another info that comes to mind, like @wvangeem 's environment, our devices use a 4G LTE internet connection via a Cradlepoint (this is our only option). Seems like there is a common thread there.
@huguesBouvier do you have any ideas why iotedged
has trouble downloading edgeAgent
? It is highly unlikely to be firewall policies because not all devices of ours have that issue. Also, if edgeAgent
does somehow get initialized it in turn has trouble downloading all modules defined in our deployments. Perhaps another clue is that on devices with such issues, iotedge check
returns inconsistent connectivity check results.
Hum, I don't know. This seems like a separate issue. Could you create a different ticket for this? What I can say is that edgeAgent somehow is getting pulled. What seem to be failing is establishing a connection with iotHub to create the edgeAgent identity. "Connection reset by peer (os error 104)" It seems that IoTHub is not happy about something but that's hard to say with just this.
This issue can be explained: drwxr-xr-x 2 root root 4096 Oct 15 13:20 WindowMerger.sock You probably removed WindowMerger.sock while edgeAgent was still running. EdgeAgent tried to start edgeHub again but edgeHub has no more "WindowMerger.sock". When that happens, docker creates one for you with root permissions
@huguesBouvier that all makes sense, thanks. I have been digging into the networking issue and if it looks like an issue with IoT Edge I'll be sure to make a ticket. That said, my edgeAgents with the issue continually are getting this output:
<4> 2021-10-18 19:24:56.113 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/tmp/edgeAgent/backup.json) instead
I take it that this could mean more than just an undefined config, is that correct? I assume this because I know for a fact the config is defined, despite what the log suggests.
This is something different, config and workload are not related. I am not sure what's causing this but it is not the first time I have seen in on windows. Could you create a separate ticket for it? I have seen it myself once on a setup and it just synced on its own after a 3 hours and never had the issue again. I did investigate but could not get a repro. I found this workaround in our history:
get-netadapterrsc > before-disable.txt Get-NetAdapter | where InterfaceDescription -Like "Mellanox" | Disable-NetAdapterRsc get-netadapterrsc > after-disable.txt Let me know if it helps
We are not using Windows, do you know of a similar workaround for Ubuntu?
I will create a separate ticket for this as soon as I'm sure it doesn't have something to do with our hardware or networking. We are ruling things out on our end, and I will mention that I re-created the VM in question from scratch and it immediately ran into the same issue upon initial runtime install, which to me suggests it is something in the environment, not IoT Edge, that is causing the issue. That said, if it is an issue with our environment, I expect there may be at least some minor tweaks to IoT Edge that would be useful (such as better error messages) so I will make a ticket when I have more information.
Overall, version 1.1.7 has helped with the issue on our side, but it doesn't seem completely resolved. We have a few devices that had failing modules and they were failing because of mangled permissions in /var/run/iotedge/mnt
. This was after over 24 hours of proper operation so it is unclear how these modules and their sockets got into this state, but they were for some time stable.
Separately, is there a way to increase the timeout to download containers (for iotedged/edgeAgent)? Some of our devices have a weak connection and it is hard to tell if issues we are seeing on those vessels are due to this issue or bad connectivity, because edgeAgent continually times out trying to download the containers. FWIW, I actually suspect a weak connection induces this issue somehow, but I have no evidence of that yet apart from anecdotal. If I can increase the timeout to say, 3-5 minutes, that would be very helpful in understanding what's going on.
On some devices we are also seeing many errors in edgeAgent such as this:
<6> 2021-10-22 14:44:20.428 +00:00 [INF] - Executing command: "Stop module mongodb"
<6> 2021-10-22 14:44:20.429 +00:00 [INF] - Executing command: "Start module mongodb"
<3> 2021-10-22 14:44:36.556 +00:00 [ERR] - Executing command for operation ["start"] failed.
Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module mongodb: Could not start module mongodb
caused by: Could not start module mongodb
caused by: OCI runtime create failed: container_linux.go:380: starting container process caused: process_linux.go:545: container init caused: rootfs_linux.go:76: mounting "/var/lib/iotedge/mnt/mongodb.sock" to rootfs at "/var/run/iotedge/workload.sock" caused: mount through procfd: not a directory: unknown: Are you trying to mount a directory onto a file (or vice-versa)? Check if the specified host path exists and is the expected type, StatusCode:500, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 232
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 180
at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
<3> 2021-10-22 14:44:36.556 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Stop module mongodb]\n [Start module mongodb]\n [Saving mongodb to store]\n)"] failed.
Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module mongodb: Could not start module mongodb
caused by: Could not start module mongodb
caused by: OCI runtime create failed: container_linux.go:380: starting container process caused: process_linux.go:545: container init caused: rootfs_linux.go:76: mounting "/var/lib/iotedge/mnt/mongodb.sock" to rootfs at "/var/run/iotedge/workload.sock" caused: mount through procfd: not a directory: unknown: Are you trying to mount a directory onto a file (or vice-versa)? Check if the specified host path exists and is the expected type, StatusCode:500, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 232
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.StartModuleAsync(String name) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 180
at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35
at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /home/vsts/work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 67
<3> 2021-10-22 14:44:36.556 +00:00 [ERR] - Step failed in deployment 117, continuing execution. Failure when running command Command Group: (
[Stop module mongodb]
[Start module mongodb]
[Saving mongodb to store]
). Will retry in 00s.
The sockets look like this:
iotadmin@iotedge0304:~$ ls -l /var/run/iotedge/
total 0
srw-rw---- 1 iotadmin iotedge 0 Oct 22 14:35 mgmt.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 workload.sock
iotadmin@iotedge0304:~$ ls -l /var/lib/iotedge/mnt/
total 0
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 AnomalyChecker.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 blobstorageiotedge.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 BlobStorageManager.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 EdaApp.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 EdaCacher.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 edgeAgent.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 edgeHub.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 MessageLogger.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 MetaAnalyzer.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 mongodb.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 redisiotedge.sock
srw-rw-rw- 1 iotedge iotedge 0 Oct 22 14:35 WindowMerger.sock
iotadmin@iotedge0304:~$
So it doesn't seem to be the sockets that are the issue. Also, the edgeAgent logs above are the result after a clean install, Any idea what's going on here and what a workaround might be?
FYI it seems like the above edgeAgent logs were resolved by issuing a docker rm <container>
to the affected containers.
"Overall, version 1.1.7 has helped with the issue on our side, but it doesn't seem completely resolved. We have a few devices that had failing modules and they were failing because of mangled permissions in /var/run/iotedge/mnt. This was after over 24 hours of proper operation so it is unclear how these modules and their sockets got into this state, but they were for some time stable." => This happens when a module gets re/started" they either stopped on their own (crashed, stopped) or got re-deployed. Permissions will not change unless a container "start" happens. Or some other process is changing permissions.
"Overall, version 1.1.7 has helped with the issue on our side" => Yes, that issue suddenly appeared. Though it doesn't seem to happen on every setup. We have a fix merged in master: https://github.com/Azure/iotedge/pull/5698
"Separately, is there a way to increase the timeout to download containers (for iotedged/edgeAgent)?" This is not possible :(.
""/var/lib/iotedge/mnt/mongodb.sock" to rootfs at "/var/run/iotedge/workload.sock" caused: mount through procfd: not a directory: unknown: Are you trying to mount a directory onto a file (or vice-versa)? " This is strange I expected to see a root folder in its place. I don't understand the permissions, owner and group are correct. Maybe you can get more details from the docker logs?
"docker rm
If you try to bootstrap edgeAgent with an older edgeAgent, does that help? Try to put edgeAgent 1.1.4 or below in config.yaml, it will just be used to pull you edgeAgent 1.1.7 from your config in portal. However the effect would be that the mnt folder is ignored and only sockets in /var/lib/iotedge would be used. Those are managed by systemd. Maybe it helps?
Version 1.2.4:
I was able to hotfix this issue by reinstalling completely. This is Kali Linux on a RPi4B
sudo cp /etc/aziot/config.toml /var/tmp
sudo apt-get remove aziot-edge --purge sudo docker rm -f $(docker ps -a -q) sudo docker rm -f $(sudo docker ps -a -q) sudo apt-get remove --purge moby-cli sudo apt-get remove --purge moby-engine sudo apt-get remove --purge docker.io
sudo systemctl start docker sudo systemctl enable docker --now
sudo curl -L "https://github.com/Azure/azure-iotedge/releases/download/1.2.4/aziot-identity-service_1.2.3-1_debian10_arm64.deb" -o aziot-identity-service.deb sudo echo "\n" | sudo DEBIAN_FRONTEND=noninteractive apt-get install ./aziot-identity-service.deb -y sudo curl -L "https://github.com/Azure/azure-iotedge/releases/download/1.2.4/aziot-edge_1.2.4-1_debian10_arm64.deb" -o aziot-edge.deb sudo echo "\n" | sudo DEBIAN_FRONTEND=noninteractive apt-get install ./aziot-edge.deb -y
sudo systemctl enable aziot-identityd.service --now sudo systemctl enable aziot-keyd.service --now sudo systemctl enable aziot-certd.service --now sudo systemctl enable aziot-edged.service --now
sudo apt install docker.io -y
sudo cp /var/tmp/config.toml /etc/aziot/
sudo iotedge config apply
This issue almost singlehandedly ruined our product...
@cgrundem Sorry to hear that, we have a patch on the way.
That aside, we have a fix but we are still trying to figure out how that issue is happening. Did that issue disappear after you re-installed everything? How many time have you restarted IoTEdge successfully after that (The issue is intermittent so you might have been lucky)?
Any restarts of docker or edge after the initial issue will not make it work. Only a reinstall can, for us. After the reinstall, there is no assurance that it will not happen again. It just makes it able to work for the time being.
If we change networks, the issue will happen probably upwards of 50% of the time.
For example, my coworker would go from home (works upon reboot etc) -> office (sometimes works, sometimes fails with socket error) -> home (sometimes fails with socket error, sometimes works). The office has poor Wifi, and some strange network configuration.
Otherwise, I’ve seen it happen randomly (but very rarely) while on the same internet.
It is more likely to happen upon overheat of the LAN on the RPi, for sure. More generally, if the Wifi strength is poor, it will fail easier as well.
Another issue we had to workaround is edge failing with a runtime error after reboots with no internet. There is another post on the issues here about that I think.
@cgrundem Instead of re-installing, this is the workaround: Check your folder: “ls -l /var/lib/iotedge/mnt” And “ls -l /var/run/iotedge/” You should see something like this for workload: image and like this for management: image
The workaround is to: Stop iotedge first Delete those sockets Restart.
Also using edgeAgent 1.2.3 or below in config.yaml might help.
FYI @huguesBouvier my team has determined the root cause of the issue quoted below was from a hardware issue in our network setup. Now that we have resolved the issue at the hardware level there is no issue as far as we're aware of. As such, I won't be creating a separate ticket for the below.
@huguesBouvier that all makes sense, thanks. I have been digging into the networking issue and if it looks like an issue with IoT Edge I'll be sure to make a ticket. That said, my edgeAgents with the issue continually are getting this output:
<4> 2021-10-18 19:24:56.113 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/tmp/edgeAgent/backup.json) instead
I take it that this could mean more than just an undefined config, is that correct? I assume this because I know for a fact the config is defined, despite what the log suggests.
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.
We have observed this problem on devices running iotedge 1.1.8 after being upgraded to 1.4. The aziot edge config still points to the 1.1 agent as bootstrap module
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
We have the same error on 1.3 today on a production environment and edgeHub is down so we are missing data! Any news on a solution in these releases?
We encounter this issue with 1.4.29, with a container stuck in a startup loop.
$ docker start pxeBoot
Error response from daemon: failed to create task for container: failed to create shim task: OCI runtime create failed: runc create failed: unable to start container process: error during container init: error mounting "/var/lib/aziot/edged/mnt/pxeBoot.sock" to rootfs at "/var/run/iotedge/workload.sock": mount /var/lib/aziot/edged/mnt/pxeBoot.sock:/var/run/iotedge/workload.sock (via /proc/self/fd/6), flags: 0x5000: not a directory: unknown: Are you trying to mount a directory onto a file (or vice-versa)? Check if the specified host path exists and is the expected type
Error: failed to start containers: pxeBoot
Executing docker rm pxeBoot
resolved the issue right away.
<3> 2024-04-19 16:57:57.077 +00:00 [ERR] - Executing command for operation ["start"] failed. Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module pxeBoot: runtime operation error: start module "pxeBoot", StatusCode:400, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleMa> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersion> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 180 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 145 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 <3> 2024-04-19 16:57:57.079 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Stop module pxeBoot]\n [Start module pxeBoot]\n [Saving pxeBoot to store]\n)"] failed. Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module pxeBoot: runtime operation error: start module "pxeBoot", StatusCode:400, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleMa> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersion> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 180 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.< b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 145 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 <3> 2024-04-19 16:57:57.082 +00:00 [ERR] - Step failed in deployment 3, continuing execution. Failure when running command Command Group: ( [Stop module pxeBoot] [Start module pxeBoot] [Saving pxeBoot to store] ). Will retry in 00s. <3> 2024-04-19 16:57:57.083 +00:00 [ERR] - Edge agent plan execution failed. System.AggregateException: One or more errors occurred. (Error calling start module pxeBoot: runtime operation error: start module "pxeBoot") ---> Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module pxeBoot: runtime operation error: start module "pxeBoot", StatusCode:400, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.Mo> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersion> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 180 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.< b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 145 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.c> --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.<>c. b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 129 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208 <4> 2024-04-19 16:57:57.127 +00:00 [WRN] - Reconcile failed because of the an exception System.AggregateException: One or more errors occurred. (Error calling start module pxeBoot: runtime operation error: start module "pxeBoot") ---> Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module pxeBoot: runtime operation error: start module "pxeBoot", StatusCode:400, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.Mo> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersion> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 180 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.< b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 145 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.Throttle[T](Func`1 identityOperation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 164 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 at Microsoft.Azure.Devices.Edge.Agent.Core.Commands.GroupCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/commands/GroupCommand.cs:line 35 at Microsoft.Azure.Devices.Edge.Agent.Core.LoggingCommandFactory.LoggingCommand.ExecuteAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/LoggingCommandFactory.cs:line 69 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.c> --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.<>c. b__7_0(List`1 f) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/planrunner/OrdererdRetryPlanRunner.cs:line 129 at Microsoft.Azure.Devices.Edge.Agent.Core.PlanRunner.OrderedRetryPlanRunner.ExecuteAsync(Int64 deploymentId, Plan plan, CancellationToken token) at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208 at Microsoft.Azure.Devices.Edge.Agent.Core.Agent.ReconcileAsync(CancellationToken token) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/Agent.cs:line 208
Might be related to this issue?
<!--Must NOT UPGRADE this package - see: https://github.com/Azure/azure-iot-sdk-csharp/issues/3413 -->
<!--<PackageReference Include="Microsoft.Azure.Devices.Provisioning.Client" Version="1.19.2" />-->
1.19.2 works, while the latest version will fail the MQTT connection. Only took me something like 5 days of effort to find this, as the error is obscure.
HTH, Richard
From: Gabríel Arthúr Pétursson @.> Sent: April 19, 2024 10:16 AM To: Azure/iotedge @.> Cc: Subscribed @.***> Subject: Re: [Azure/iotedge] Connections refused (err 111) connecting to unix:///var/run/iotedge/workload.sock after edgeAgent restart (#5505)
We encounter this issue with 1.4.29, with a container stuck in a startup loop.
$ docker start pxeBoot Error response from daemon: failed to create task for container: failed to create shim task: OCI runtime create failed: runc create failed: unable to start container process: error during container init: error mounting "/var/lib/aziot/edged/mnt/pxeBoot.sock" to rootfs at "/var/run/iotedge/workload.sock": mount /var/lib/aziot/edged/mnt/pxeBoot.sock:/var/run/iotedge/workload.sock (via /proc/self/fd/6), flags: 0x5000: not a directory: unknown: Are you trying to mount a directory onto a file (or vice-versa)? Check if the specified host path exists and is the expected type Error: failed to start containers: pxeBoot
Executing docker rm pxeBoot resolved the issue right away.
edgeAgent logs
<3> 2024-04-19 16:57:57.077 +00:00 [ERR] - Executing command for operation ["start"] failed. Microsoft.Azure.Devices.Edge.Agent.Edgelet.EdgeletCommunicationException- Message:Error calling start module pxeBoot: runtime operation error: start module "pxeBoot", StatusCode:400, at: at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleMa> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.Execute[T](Func`1 func, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersion> at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2022_08_03.ModuleManagementHttpClient.StartModuleAsync(String name) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2022_08_03/ModuleManagementHttpClient.cs:line 180 at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass26_0.
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 thensudo 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:
iotedge restart edgeAgent
.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
Runtime Versions
iotedge version
]: iotedge 1.1.6docker 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: trueServer: 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
insteadLogs
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
: