iotedge: EdgeAgent 1.2.6 thows many exceptions when updating custom modules
Expected Behavior
EdgeAgent should not throw errors.
Current Behavior
We have a problem where we want to update a number of custom modules on a number of devices running iot edge runtime, 1.2.7. edgeAgent and edgeHub run 1.2.6. Some devices downloads and installs the updated custom modules within 15-20 min from the time we add a layerdeployment for the update in the iot hub in azure. However some takes much longer to update, up to an hour. When looking in the logs for edgeAgent we see a number of suspicious exceptions.
The container regestry we are using is hosted in azure.
Context (Environment)
Device Information
- Host OS: Custom build of Raspberry Pi OS buster.
- Architecture: ARM32v7
Runtime Versions
- aziot-edged [run
iotedge version]: 1.2.7 - Edge Agent [image tag (e.g. 1.0.0)]: 1.2.6
- Edge Hub [image tag (e.g. 1.0.0)]: 1.2.6
- Docker/Moby [run
docker version]: 3.0.13+azure
Logs
Log from edgeAgent
2022-03-15 10:47:10 +00:00 Starting Edge Agent
2022-03-15 10:47:10 +00:00 Changing ownership of storage folder: /iotedge/storage//edgeAgent to 1000
2022-03-15 10:47:10 +00:00 Changing ownership of management socket: /var/run/iotedge/mgmt.sock
2022-03-15 10:47:11.335 +00:00 Edge Agent Main()
<6> 2022-03-15 10:47:12.242 +00:00 [INF] - Initializing Edge Agent.
<6> 2022-03-15 10:47:12.803 +00:00 [INF] - Version - 1.2.6.48918552 (e15b86b2783d64b6136b15fcd09e3584269c3be1)
<6> 2022-03-15 10:47:12.804 +00:00 [INF] -
█████╗ ███████╗██╗ ██╗██████╗ ███████╗
██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝
███████║ ███╔╝ ██║ ██║██████╔╝█████╗
██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝
██║ ██║███████╗╚██████╔╝██║ ██║███████╗
╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝
██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗
██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝
██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗
██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝
██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗
╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝
<6> 2022-03-15 10:47:12.932 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false}
<6> 2022-03-15 10:47:13.303 +00:00 [INF] - Installing certificates [CN=iotedged workload ca edge-dev-pi:06/13/2022 10:47:09] to Root
<6> 2022-03-15 10:47:13.628 +00:00 [INF] - Starting metrics listener on Host: *, Port: 9600, Suffix: metrics
<6> 2022-03-15 10:47:13.780 +00:00 [INF] - Updating performance metrics every 05m:00s
<6> 2022-03-15 10:47:13.796 +00:00 [INF] - Started operation Get system resources
<6> 2022-03-15 10:47:13.801 +00:00 [INF] - Collecting metadata metrics
<6> 2022-03-15 10:47:14.018 +00:00 [INF] - Set metadata metrics: 1.2.6.48918552 (e15b86b2783d64b6136b15fcd09e3584269c3be1), {"Enabled":false,"DisableCloudSubscriptions":false}, {"OperatingSystemType":"linux","Architecture":"armv7l","Version":"1.2.7","Provisioning":{"Type":"ProvisioningType","DynamicReprovisioning":false,"AlwaysReprovisionOnStartup":false},"ServerVersion":"3.0.13+azure","KernelVersion":"5.10.63-v7l+","OperatingSystem":"Raspbian GNU/Linux 10 (buster)","NumCpus":4,"Virtualized":"no"}, True
<6> 2022-03-15 10:47:14.069 +00:00 [INF] - Started operation Checkpoint Availability
<6> 2022-03-15 10:47:14.086 +00:00 [INF] - Started operation refresh twin config
<6> 2022-03-15 10:47:14.135 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_Tcp_Only...
<6> 2022-03-15 10:47:15.155 +00:00 [INF] - Created persistent store at /iotedge/storage/edgeAgent
<6> 2022-03-15 10:47:15.354 +00:00 [INF] - Started operation Metrics Scrape
<6> 2022-03-15 10:47:15.355 +00:00 [INF] - Started operation Metrics Upload
Scraping frequency: 01:00:00
Upload Frequency: 1.00:00:00
<6> 2022-03-15 10:47:16.025 +00:00 [INF] - Registering request handler UploadModuleLogs
<6> 2022-03-15 10:47:16.025 +00:00 [INF] - Registering request handler GetModuleLogs
<6> 2022-03-15 10:47:16.026 +00:00 [INF] - Registering request handler UploadSupportBundle
<6> 2022-03-15 10:47:16.026 +00:00 [INF] - Registering request handler RestartModule
<4> 2022-03-15 10:47:21.751 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/iotedge/storage/edgeAgent/backup.json) instead
<6> 2022-03-15 10:47:21.890 +00:00 [INF] - Obtained edge agent config from backup config file - /iotedge/storage/edgeAgent/backup.json
<6> 2022-03-15 10:47:22.377 +00:00 [INF] - Plan execution started for deployment 695
<6> 2022-03-15 10:47:22.386 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module G]\n [Start module G]\n [Saving G to store]\n)"
<6> 2022-03-15 10:47:22.398 +00:00 [INF] - Executing command: "Stop module G"
<6> 2022-03-15 10:47:22.462 +00:00 [INF] - Executing command: "Start module G"
<6> 2022-03-15 10:47:22.859 +00:00 [INF] - Executing command: "Saving G to store"
<6> 2022-03-15 10:47:22.883 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module E]\n [Start module E]\n [Saving E to store]\n)"
<6> 2022-03-15 10:47:22.883 +00:00 [INF] - Executing command: "Stop module E"
<6> 2022-03-15 10:47:22.893 +00:00 [INF] - Executing command: "Start module E"
<6> 2022-03-15 10:47:23.167 +00:00 [INF] - Executing command: "Saving E to store"
<6> 2022-03-15 10:47:23.180 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module D]\n [Start module D]\n [Saving D to store]\n)"
<6> 2022-03-15 10:47:23.182 +00:00 [INF] - Executing command: "Stop module D"
<6> 2022-03-15 10:47:23.200 +00:00 [INF] - Executing command: "Start module D"
<6> 2022-03-15 10:47:23.537 +00:00 [INF] - Executing command: "Saving D to store"
<6> 2022-03-15 10:47:23.542 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module edgeHub]\n [Start module edgeHub]\n [Saving edgeHub to store]\n)"
<6> 2022-03-15 10:47:23.543 +00:00 [INF] - Executing command: "Stop module edgeHub"
<6> 2022-03-15 10:47:23.592 +00:00 [INF] - Executing command: "Start module edgeHub"
<6> 2022-03-15 10:47:25.351 +00:00 [INF] - Executing command: "Saving edgeHub to store"
<6> 2022-03-15 10:47:25.375 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module C]\n [Start module C]\n [Saving C to store]\n)"
<6> 2022-03-15 10:47:25.376 +00:00 [INF] - Executing command: "Stop module C"
<6> 2022-03-15 10:47:25.435 +00:00 [INF] - Executing command: "Start module C"
<6> 2022-03-15 10:47:25.935 +00:00 [INF] - Executing command: "Saving C to store"
<6> 2022-03-15 10:47:25.938 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module A]\n [Start module A]\n [Saving A to store]\n)"
<6> 2022-03-15 10:47:25.939 +00:00 [INF] - Executing command: "Stop module A"
<6> 2022-03-15 10:47:25.954 +00:00 [INF] - Executing command: "Start module A"
<6> 2022-03-15 10:47:26.519 +00:00 [INF] - Executing command: "Saving A to store"
<6> 2022-03-15 10:47:26.526 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module H]\n [Start module H]\n [Saving H to store]\n)"
<6> 2022-03-15 10:47:26.543 +00:00 [INF] - Executing command: "Stop module H"
<6> 2022-03-15 10:47:26.558 +00:00 [INF] - Executing command: "Start module H"
<6> 2022-03-15 10:47:27.156 +00:00 [INF] - Executing command: "Saving H to store"
<6> 2022-03-15 10:47:27.175 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module F]\n [Start module F]\n [Saving F to store]\n)"
<6> 2022-03-15 10:47:27.176 +00:00 [INF] - Executing command: "Stop module F"
<6> 2022-03-15 10:47:27.190 +00:00 [INF] - Executing command: "Start module F"
<6> 2022-03-15 10:47:27.688 +00:00 [INF] - Executing command: "Saving F to store"
<6> 2022-03-15 10:47:27.691 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module B]\n [Start module B]\n [Saving B to store]\n)"
<6> 2022-03-15 10:47:27.691 +00:00 [INF] - Executing command: "Stop module B"
<6> 2022-03-15 10:47:27.716 +00:00 [INF] - Executing command: "Start module B"
<6> 2022-03-15 10:47:28.362 +00:00 [INF] - Executing command: "Saving B to store"
<6> 2022-03-15 10:47:28.366 +00:00 [INF] - Plan execution ended for deployment 695
<4> 2022-03-15 10:47:38.827 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/iotedge/storage/edgeAgent/backup.json) instead
<6> 2022-03-15 10:47:45.027 +00:00 [INF] - Edge agent attempting to connect to IoT Hub via Amqp_WebSocket_Only...
<6> 2022-03-15 11:37:18.993 +00:00 [INF] - Edge agent connected to IoT Hub via Amqp_WebSocket_Only.
<4> 2022-03-15 11:37:19.353 +00:00 [WRN] - Empty edge agent config was received. Attempting to read config from backup (/iotedge/storage/edgeAgent/backup.json) instead
<6> 2022-03-15 11:37:19.392 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'G' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.393 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'E' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.393 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'D' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.394 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'edgeHub' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.394 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'C' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.395 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'A' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.395 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'H' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.396 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'F' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.396 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'B' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:37:19.397 +00:00 [INF] - Plan execution started for deployment 695
<6> 2022-03-15 11:37:19.399 +00:00 [INF] - Executing command: "Saving G to store"
<6> 2022-03-15 11:37:19.408 +00:00 [INF] - Executing command: "Saving E to store"
<6> 2022-03-15 11:37:19.409 +00:00 [INF] - Executing command: "Saving D to store"
<6> 2022-03-15 11:37:19.410 +00:00 [INF] - Executing command: "Saving edgeHub to store"
<6> 2022-03-15 11:37:19.410 +00:00 [INF] - Executing command: "Saving C to store"
<6> 2022-03-15 11:37:19.410 +00:00 [INF] - Executing command: "Saving A to store"
<6> 2022-03-15 11:37:19.411 +00:00 [INF] - Executing command: "Saving H to store"
<6> 2022-03-15 11:37:19.411 +00:00 [INF] - Executing command: "Saving F to store"
<6> 2022-03-15 11:37:19.412 +00:00 [INF] - Executing command: "Saving B to store"
<6> 2022-03-15 11:37:19.412 +00:00 [INF] - Plan execution ended for deployment 695
<6> 2022-03-15 11:37:19.447 +00:00 [INF] - Initialized new module client with subscriptions enabled
<6> 2022-03-15 11:37:19.666 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 695 and reported properties version 1134.
<6> 2022-03-15 11:37:25.765 +00:00 [INF] - Updated reported properties
<6> 2022-03-15 11:37:52.515 +00:00 [INF] - Module 'C' scheduled to restart after 10s (06s left).
<6> 2022-03-15 11:37:52.820 +00:00 [INF] - Updated reported properties
<6> 2022-03-15 11:37:57.923 +00:00 [INF] - Module 'C' scheduled to restart after 10s (00s left).
<6> 2022-03-15 11:38:03.079 +00:00 [INF] - Plan execution started for deployment 695
<6> 2022-03-15 11:38:03.079 +00:00 [INF] - Executing command: "Command Group: (\n [Stop module C]\n [Start module C]\n [Saving C to store]\n)"
<6> 2022-03-15 11:38:03.080 +00:00 [INF] - Executing command: "Stop module C"
<6> 2022-03-15 11:38:03.090 +00:00 [INF] - Executing command: "Start module C"
<6> 2022-03-15 11:38:03.380 +00:00 [INF] - Executing command: "Saving C to store"
<6> 2022-03-15 11:38:03.381 +00:00 [INF] - Plan execution ended for deployment 695
<6> 2022-03-15 11:38:08.768 +00:00 [INF] - Updated reported properties
<6> 2022-03-15 11:48:05.264 +00:00 [INF] - HealthRestartPlanner is clearing restart stats for module 'C' as it has been running healthy for 00:10:00.
<6> 2022-03-15 11:48:05.265 +00:00 [INF] - Plan execution started for deployment 695
<6> 2022-03-15 11:48:05.265 +00:00 [INF] - Executing command: "Saving C to store"
<6> 2022-03-15 11:48:05.266 +00:00 [INF] - Plan execution ended for deployment 695
<6> 2022-03-15 11:48:10.721 +00:00 [INF] - Updated reported properties
<6> 2022-03-15 12:36:44.547 +00:00 [INF] - Starting periodic operation refresh twin config...
<6> 2022-03-15 12:36:44.773 +00:00 [INF] - Obtained Edge agent twin from IoTHub with desired properties version 695 and reported properties version 1138.
<6> 2022-03-15 12:36:44.783 +00:00 [INF] - Successfully completed periodic operation refresh twin config
<6> 2022-03-15 12:36:45.815 +00:00 [INF] - Starting periodic operation Metrics Scrape...
<6> 2022-03-15 12:36:45.823 +00:00 [INF] - Scraping Metrics
<6> 2022-03-15 12:36:45.841 +00:00 [INF] - Scraping endpoint http://edgeHub:9600/metrics
<6> 2022-03-15 12:36:46.020 +00:00 [INF] - Scraping endpoint http://edgeAgent:9600/metrics
<6> 2022-03-15 12:36:46.294 +00:00 [INF] - Storing Metrics
<6> 2022-03-15 12:36:46.571 +00:00 [INF] - Scraped and Stored Metrics
<6> 2022-03-15 12:36:46.571 +00:00 [INF] - Successfully completed periodic operation Metrics Scrape
<6> 2022-03-15 12:42:59.012 +00:00 [INF] - Plan execution started for deployment 696
<6> 2022-03-15 12:42:59.012 +00:00 [INF] - Executing command: "Saving E to store"
<6> 2022-03-15 12:42:59.013 +00:00 [INF] - Executing command: "Saving G to store"
<6> 2022-03-15 12:42:59.014 +00:00 [INF] - Executing command: "Saving F to store"
<6> 2022-03-15 12:42:59.014 +00:00 [INF] - Executing command: "Saving H to store"
<6> 2022-03-15 12:42:59.015 +00:00 [INF] - Executing command: "Saving D to store"
<6> 2022-03-15 12:42:59.015 +00:00 [INF] - Executing command: "Saving A to store"
<6> 2022-03-15 12:42:59.016 +00:00 [INF] - Executing command: "Saving C to store"
<6> 2022-03-15 12:42:59.016 +00:00 [INF] - Executing command: "Saving B to store"
<6> 2022-03-15 12:42:59.070 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module E]\n [Stop module E]\n [Update module E]\n)]\n [Start module E]\n)"
<6> 2022-03-15 12:42:59.070 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module E]\n [Stop module E]\n [Update module E]\n)"
<3> 2022-03-15 12:44:39.132 +00:00 [ERR] - Executing command for operation ["update"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
<3> 2022-03-15 12:44:39.223 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Command Group: (\n [Prepare update module E]\n [Stop module E]\n [Update module E]\n)]\n [Start module E]\n)"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
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 67
<3> 2022-03-15 12:44:39.231 +00:00 [ERR] - Step failed in deployment 696, continuing execution. Failure when running command Command Group: (
[Command Group: (
[Prepare update module E]
[Stop module E]
[Update module E]
)]
[Start module E]
). Will retry in 00s.
<6> 2022-03-15 12:44:39.233 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module G]\n [Stop module G]\n [Update module G]\n)]\n [Start module G]\n)"
<6> 2022-03-15 12:44:39.233 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module G]\n [Stop module G]\n [Update module G]\n)"
<3> 2022-03-15 12:46:19.268 +00:00 [ERR] - Executing command for operation ["update"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
<3> 2022-03-15 12:46:19.326 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Command Group: (\n [Prepare update module G]\n [Stop module G]\n [Update module G]\n)]\n [Start module G]\n)"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
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 67
<3> 2022-03-15 12:46:19.366 +00:00 [ERR] - Step failed in deployment 696, continuing execution. Failure when running command Command Group: (
[Command Group: (
[Prepare update module G]
[Stop module G]
[Update module G]
)]
[Start module G]
). Will retry in 00s.
<6> 2022-03-15 12:46:19.368 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module F]\n [Stop module F]\n [Update module F]\n)]\n [Start module F]\n)"
<6> 2022-03-15 12:46:19.368 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module F]\n [Stop module F]\n [Update module F]\n)"
<3> 2022-03-15 12:47:59.397 +00:00 [ERR] - Executing command for operation ["update"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
<3> 2022-03-15 12:47:59.447 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Command Group: (\n [Prepare update module F]\n [Stop module F]\n [Update module F]\n)]\n [Start module F]\n)"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
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 67
<3> 2022-03-15 12:47:59.468 +00:00 [ERR] - Step failed in deployment 696, continuing execution. Failure when running command Command Group: (
[Command Group: (
[Prepare update module F]
[Stop module F]
[Update module F]
)]
[Start module F]
). Will retry in 00s.
<6> 2022-03-15 12:47:59.470 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module H]\n [Stop module H]\n [Update module H]\n)]\n [Start module H]\n)"
<6> 2022-03-15 12:47:59.470 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module H]\n [Stop module H]\n [Update module H]\n)"
<6> 2022-03-15 12:49:02.538 +00:00 [INF] - Executing command: "Start module H"
<6> 2022-03-15 12:49:02.767 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module D]\n [Stop module D]\n [Update module D]\n)]\n [Start module D]\n)"
<6> 2022-03-15 12:49:02.768 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module D]\n [Stop module D]\n [Update module D]\n)"
<6> 2022-03-15 12:50:00.751 +00:00 [INF] - Executing command: "Start module D"
<6> 2022-03-15 12:50:01.085 +00:00 [INF] - Executing command: "Command Group: (\n [Command Group: (\n [Prepare update module A]\n [Stop module A]\n [Update module A]\n)]\n [Start module A]\n)"
<6> 2022-03-15 12:50:01.085 +00:00 [INF] - Executing command: "Command Group: (\n [Prepare update module A]\n [Stop module A]\n [Update module A]\n)"
<3> 2022-03-15 12:51:41.129 +00:00 [ERR] - Executing command for operation ["update"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
<3> 2022-03-15 12:51:41.155 +00:00 [ERR] - Executing command for operation ["Command Group: (\n [Command Group: (\n [Prepare update module A]\n [Stop module A]\n [Update module A]\n)]\n [Start module A]\n)"] failed.
System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at System.Threading.CancellationToken.ThrowIfCancellationRequested()
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.GetResult(Int16 token)
at System.IO.BufferedStream.ReadFromUnderlyingStreamAsync(Memory`1 buffer, CancellationToken cancellationToken, Int32 bytesAlreadySatisfied, Task semaphoreLockTask)
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpBufferedStream.ReadLineAsync(CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpBufferedStream.cs:line 62
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.SetResponseStatusLine(HttpResponseMessage httpResponse, HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 158
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpRequestResponseSerializer.DeserializeResponse(HttpBufferedStream bufferedStream, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpRequestResponseSerializer.cs:line 69
at Microsoft.Azure.Devices.Edge.Util.Uds.HttpUdsMessageHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/uds/HttpUdsMessageHandler.cs:line 48
at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.GeneratedCode.EdgeletHttpClient.PrepareUpdateModuleAsync(String api_version, String name, ModuleSpec module, CancellationToken cancellationToken) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/generatedCode/EdgeletHttpClient.cs:line 519
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Versioning.ModuleManagementHttpClientVersioned.<>c__DisplayClass35_0.<<Execute>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs:line 127
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 128
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.HandleException(Exception exception, String operation) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 245
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/ModuleManagementHttpClientVersioned.cs:line 155
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.Version_2020_07_07.ModuleManagementHttpClient.PrepareUpdateAsync(ModuleSpec moduleSpec) in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/version_2020_07_07/ModuleManagementHttpClient.cs:line 214
at Microsoft.Azure.Devices.Edge.Agent.Edgelet.ModuleManagementHttpClient.<>c__DisplayClass25_0.<<Throttle>b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs:line 128
--- End of stack trace from previous location where exception was thrown ---
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 147
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 67
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 67
<3> 2022-03-15 12:51:41.162 +00:00 [ERR] - Step failed in deployment 696, continuing execution. Failure when running command Command Group: (
[Command Group: (
[Prepare update module A]
[Stop module A]
[Update module A]
)]
[Start module A]
). Will retry in 00s.
.
.
.
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Reactions: 1
- Comments: 25 (9 by maintainers)
We’re experiencing the same exception when rolling out new module images.
Further @ancaantochi, I can confirm that we’re seeing behavior which sounds similar to that reported by @FinitelyFailed, where the previous version of the module will stop running partway through this process, and not recover until the new image has been applied.
Initially we suspected rollouts were stuck throwing exceptions and would never complete, so we rolled back. Rollbacks installed immediately because the images had already been cached. A known network issue muddied the waters but turns out not to have been relevant. We then found this open issue and have been working to assemble the following analysis to complement that from @FinitelyFailed. We have a Microsoft liaison through whom we will also escalate this issue.
Due to the varying timespans involved and the need to hit
GetLogsat regular intervals to attempt to capture the tail of one image’s output and the start of the next, it’s taken us some time to assemble full logs for this problem, which began affecting our rollouts from on or before 22 Mar 2022. Apologies, therefore, that the logs shown below are from disparate sessions.Each build of our system produces two modules
bagSealCheckerandpackingClassifier, which are deployed to an Azure Container Registry. We then apply layered deployments to our devices, which consist of:bagSealCheckerpackingClassifierbagSealChecker.So the layered deployments aggregate to an overall deployment to a device which looks like this:
bagSealChecker1bagSealChecker2bagSealChecker3packingClassifierEach
bagSealCheckerhas a module twin which configures it to monitor a separate camera feed. AllbagSealCheckers send their captured data topackingClassifierfor analysis.When we are affected by this issue, we see
$edgeAgentattempting to retrieve thebagSealCheckerimages, but hitting the above exception:At some point, the running
bagSealCheckerinstances stop running. It is unclear what triggers this, but they are not dying because of an exception - they appear to be properly stopped.For the next while,
$edgeAgentwill seem to report no exceptions, but also doesn’t seem to be up to much:At a later point, which is arbitrary and may be anywhere between 5 to 90 minutes later in our experience to date, the
bagSealCheckers start running again.At this point, all the
bagSealCheckers have come online and are responsive. They continue to talk to the OLD version ofpackingClassifier, which is happy to service these requests, so things run for a while.However,
$edgeAgentis not done and knows it still needs to updatepackingClassifier, which it starts doing following the same steps as above - choking, then stopping moduleB, then spinning for 5-to-90 mins, then finally getting the newpackingClassifierrunning:$edgeAgenthas successfully gotbagSealCheckerrunning, so starts thinking aboutpackingClassifier.$edgeAgentis throwing exceptions intermittently while trying to get thepackingClassifierimage.packingClassifieris stopped.$edgeAgentcontinues to spin whilepackingClassifieris stopped.$edgeAgentmanages to get to “Start module packingClassifier”.packingClassifierstarts. Now things are finally operational, after a significant outage (45 minutes offline forpackingClassifier; in this casebagSealCheckerwas offline for about 15 min, and there was a lull in the middle when both were running but with mismatched versions of around 35 min).Taken as a whole, this implies to me a few underlying issues. These are guesses and as you’ll see above we don’t have the low-level diagnostics which might confirm them:
$edgeAgentstops the old module before it starts building or acquiring dependencies for the new module.$edgeAgentdoesn’t wait until it’s got the full deployment module-set before rolling out what it’s acquired so far (maybe this is by design?)So far we believe that this behaviour is isolated to a specific target site, which has two IoT Edge devices. We will expand our testing today to another couple of sites to confirm that they are not affected.
Appreciate your insight re
ModuleUpdateMode, @micahl.While we haven’t solved the root problem - slowness of module acquisition - we have made some progress thanks to this thread and the engagement with the IoT Edge team:
OperationCanceledExceptionis symptomatic, not the root of the problem. It is not indicative of a genuine failure and can be disregarded.ModuleUpdateModeflagWaitForAllPullswill provide the ability to ensure that modules do not end up “out of sync” because of this delay.We look forward to release of this flag and are eager to see the expected improvements. We’ll continue to watch for evidence of slow pulls and their possible cause.
Issue is still being investigated, will update here when I have more details