Getting Cached Twin Always Takes At Least 60 Seconds

david-fitzgerald-re commented 1 year ago

I am trying to improve my module's network resilience. If we have no internet connection, I wish for the cached module twin to be retrieved quickly.

Expected Behavior

At the moment (with no internet connection) it always takes at least a minute for edgeHub to give up trying to connect to IoTHub such that it will return a cached module twin.

I believe it is related to this line in the edgeHub logs:

 ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session401.

I wish for this to be configurable, say, if you can't get the twin from IoTHub within ~10 seconds, return your cached twin.

I have attempted to configure all of the time-related environment variables possible defined within this file but sadly none of them are causing the desired effect of a shorter fallback to using the cached twin.

We should be able to use environment variables to configure how long it takes for a client (a python IoTHubModuleClient specifically) to timeout such that a get_twin call will fallback to a local version of the twin which edgeHub caches.

Basically, I would like the results to look like this:

Func create_from_edge_environment took 0.24739779000810813
Func get_twin took 10.0

Current Behavior

Without an internet connection, it takes this long to retrieve the (cached) twin:

Func create_from_edge_environment took 0.24739779000810813
Func get_twin took 80.08789820699894

With an internet connection it takes this long to retrieve the (non-cached) twin:

Func create_from_edge_environment took 0.21544561300834175
Func get_twin took 0.18774236600438599

Steps to Reproduce

Deploy a manifest with these env vars set for edgeHub and edgeAgent. Additionally add a custom module to the manifest - it can basically be empty, just with python installed.

       ...
        "systemModules": {
          "edgeAgent": {
            "type": "docker",
            "settings": {
              "image": "mcr.microsoft.com/azureiotedge-agent:1.4.14",
              "createOptions": {
                "HostConfig": {
                  "LogConfig": {
                    "Type": "json-file",
                    "Config": {
                      "max-size": "10m",
                      "max-file": "3"
                    }
                  },
                  "Binds": [
                    "edgeagent-temp:/tmp/edgeAgent"
                  ],
                  "Dns": [
                    "1.1.1.1",
                    "8.8.8.8"
                  ]
                }
              }
            },
            "env": {
              "SendRuntimeQualityTelemetry": {
                "value": "false"
              },
              "DisableDeviceAnalyticsMetadata": {
                "value": "true"
              },
              "CloudConnectionIdleTimeoutSecs": {
                "value": 10
              },
              "CloseCloudConnectionOnIdleTimeout": {
                "value": true
              }
            }
          },
          "edgeHub": {
            "type": "docker",
            "status": "running",
            "restartPolicy": "always",
            "settings": {
              "image": "mcr.microsoft.com/azureiotedge-hub:1.4.14",
              "createOptions": {
                "HostConfig": {
                  "LogConfig": {
                    "Type": "json-file",
                    "Config": {
                      "max-size": "10m",
                      "max-file": "3"
                    }
                  },
                  "Dns": [
                    "1.1.1.1",
                    "8.8.8.8"
                  ]
                }
              }
            },
            "env": {
              "OptimizeForPerformance": {
                "value": "false"
              },
              "ServerCertificateRenewAfterInMs": {
                "value": "864000000"
              },
              "MaxUpstreamBatchSize": {
                "value": 50
              },
              "CloudOperationTimeoutSecs": {
                "value": 10
              },
              "MinTwinSyncPeriodSecs": {
                "value": 10
              },
              "CloudConnectionHangingTimeoutSecs": {
                "value": 10
              },
              "ConnectivityCheckFrequencySecs": {
                "value": 10
              }
            }
          }
        },
      ...

In the custom module, open an ipython terminal (python itself is probably fine)
On the docker host, simulate a network outage with the following iptables command (inspired by this but adapted with this in mind)
```
sudo iptables -I DOCKER-USER -i eth0 ! -s 192.168.1.0/24 -j DROP
```
Note: this is run on the docker host (on the device) not on the custom module
Immediately after, run this code in the ipython shell:

from time import perf_counter
from typing import Callable, TypeVar, Any
from azure.iot.device import IoTHubModuleClient as SyncClient

T = TypeVar("T")

def time_it(func: Callable[[Any], T]):
    def wrapper(*args, **kwargs) -> T:
        start = perf_counter()
        ret_val = func(*args, **kwargs)
        print(f"Func {func.__name__} took {perf_counter() - start}")
        return ret_val

    return wrapper

client = time_it(SyncClient.create_from_edge_environment)(product_info="REDACTED-module-net-test")
twin = time_it(client.get_twin)()

Observe that the output takes at least 60 seconds.

Func create_from_edge_environment took 0.24739779000810813
Func get_twin took 80.08789820699894

Clean up the rule:

sudo iptables -D DOCKER-USER 1

Context (Environment)

pip azure-iot-device 2.12.0 on my module

Output of `iotedge check`

Click here

``` REDACTED-user@REDACTED-device:~$ sudo iotedge check --iothub-hostname <<>> --verbose Configuration checks (aziot-identity-service) --------------------------------------------- √ keyd configuration is well-formed - OK √ certd configuration is well-formed - OK √ tpmd configuration is well-formed - OK √ identityd configuration is well-formed - OK √ daemon configurations up-to-date with config.toml - OK √ identityd config toml file specifies a valid hostname - OK √ aziot-identity-service package is up-to-date - OK √ host time is close to reference time - OK √ production readiness: identity certificates expiry - OK √ preloaded certificates are valid - OK √ keyd is running - OK √ certd is running - OK √ identityd is running - OK √ read all preloaded certificates from the Certificates Service - OK √ read all preloaded key pairs from the Keys Service - OK √ check all EST server URLs utilize HTTPS - OK √ ensure all preloaded certificates match preloaded private keys with the same ID - OK Connectivity checks (aziot-identity-service) -------------------------------------------- √ host can connect to and perform TLS handshake with iothub AMQP port - OK √ host can connect to and perform TLS handshake with iothub HTTPS / WebSockets port - OK √ host can connect to and perform TLS handshake with iothub MQTT port - OK √ host can connect to and perform TLS handshake with DPS endpoint - OK Configuration checks -------------------- √ aziot-edged configuration is well-formed - OK √ configuration up-to-date with config.toml - OK √ container engine is installed and functional - OK √ configuration has correct URIs for daemon mgmt endpoint - OK √ aziot-edge package is up-to-date - OK √ container time is close to host time - OK √ DNS server - 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 - Warning The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. caused by: The edgeHub module is not configured to persist its /tmp/edgeHub directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. √ Agent image is valid and can be pulled from upstream - OK √ proxy settings are consistent in aziot-edged, aziot-identityd, moby daemon and config.toml - OK Connectivity checks ------------------- √ container on the default network can connect to upstream AMQP port - OK √ container on the default network can connect to upstream HTTPS / WebSockets port - OK √ container on the default network can connect to upstream MQTT port - OK skipping because of not required in this configuration √ container on the IoT Edge module network can connect to upstream AMQP port - OK √ container on the IoT Edge module network can connect to upstream HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to upstream MQTT port - OK skipping because of not required in this configuration 36 check(s) succeeded. 1 check(s) raised warnings. 2 check(s) were skipped due to errors from other checks. ```

Device Information

Host OS: Ubuntu 20.04.6 LTS (NVIDIA Jetson Orin)
Architecture: aarch64
Container OS: Ubuntu 20.04.6 LTS

Runtime Versions

aziot-edged: 1.4.20
Edge Agent: 1.4.14
Edge Hub: 1.4.14
Docker: 24.0.7

Logs

edge-agent logs

``` I decided to remove the `edgeAgent` logs because the GH issue description exceeded the maximum character limit. I have got it saved and can post if requested. ```

edge-hub logs

``` <6> 2023-11-13 17:32:41.017 +00:00 [INF] - Successfully generated identity for clientId REDACTED-device/REDACTED-module and username REDACTED-host/REDACTED-device/REDACTED-module/?api-version=2019-10-01&DeviceClientType=azure-iot-device-iothub-py%2F2.12.0%283.8.10%3BLinux%20%231%20SMP%20PREEMPT%20Tue%20Jan%2024%2015%3A09%3A44%20PST%202023%3Baarch64%REDACTED-module-net-test <6> 2023-11-13 17:32:41.017 +00:00 [INF] - "ClientAuthenticated, REDACTED-device/REDACTED-module, 53ce12cb" <6> 2023-11-13 17:32:41.018 +00:00 [INF] - New device connection for device REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:41.018 +00:00 [INF] - Client REDACTED-device/REDACTED-module connected to edgeHub, processing existing subscriptions. <6> 2023-11-13 17:32:41.018 +00:00 [INF] - Bind device proxy for device REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:41.018 +00:00 [INF] - Binding message channel for device Id REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:41.018 +00:00 [INF] - Processing pending subscriptions for REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:41.019 +00:00 [INF] - Processing subscriptions TwinResponse for client REDACTED-device/REDACTED-module. <6> 2023-11-13 17:32:41.019 +00:00 [INF] - Processing pending subscriptions for REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:41.020 +00:00 [INF] - Set subscriptions from session state for REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:50.265 +00:00 [INF] - Error due to sdk hanging and upstream call timed out, closing cloud proxy for REDACTED-device/$edgeHub. Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubCloudSDKException: Operation timed out due to SDK hanging at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.<>c.<.cctor>b__43_0() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 51 at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 229 <6> 2023-11-13 17:32:50.266 +00:00 [INF] - Exiting connected state <6> 2023-11-13 17:32:50.266 +00:00 [INF] - Entering unreachable state <6> 2023-11-13 17:32:50.267 +00:00 [INF] - Entering disconnected state <6> 2023-11-13 17:32:50.270 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.270 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.270 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/REDACTED-module is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/REDACTED-module changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/REDACTED-module is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/REDACTED-module changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/$edgeHub is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/$edgeHub changed to Disconnected <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Cloud connection for REDACTED-device/REDACTED-module is False <6> 2023-11-13 17:32:50.271 +00:00 [INF] - Connection status for REDACTED-device/REDACTED-module changed to Disconnected <6> 2023-11-13 17:32:50.272 +00:00 [INF] - Retrying cloud proxy operation UpdateReportedPropertiesAsync for REDACTED-device/$edgeHub. System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> System.TimeoutException: The operation has timed out. at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.RoundTripTwinMessageAsync(AmqpTwinMessageType amqpTwinMessageType, TwinCollection reportedProperties, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass36_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.SendTwinPatchAsync(TwinCollection reportedProperties, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.UpdateReportedPropertiesAsync(TwinCollection reportedProperties) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.UpdateReportedPropertiesAsync(TwinCollection reportedProperties) at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 229 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 229 at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.<>c__DisplayClass24_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 65 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 76 <6> 2023-11-13 17:32:51.022 +00:00 [INF] - Error due to sdk hanging and upstream call timed out, closing cloud proxy for REDACTED-device/REDACTED-module. Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubCloudSDKException: Operation timed out due to SDK hanging at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.<>c.<.cctor>b__43_0() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 51 at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 137 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.GetTwinAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 145 <6> 2023-11-13 17:32:51.023 +00:00 [INF] - Closing receiver in cloud proxy 19698703-e7ca-4462-aa50-5de96701bab1 for REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:51.023 +00:00 [INF] - Closed cloud proxy 19698703-e7ca-4462-aa50-5de96701bab1 for REDACTED-device/REDACTED-module <6> 2023-11-13 17:32:51.023 +00:00 [INF] - Retrying cloud proxy operation GetTwinAsync for REDACTED-device/REDACTED-module. Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubCloudSDKException: Operation timed out due to SDK hanging at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.<>c.<.cctor>b__43_0() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 51 at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter[T](Task`1 task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 137 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.GetTwinAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 145 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.GetTwinAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 145 at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) <6> 2023-11-13 17:33:00.271 +00:00 [INF] - Closing receiver in cloud proxy 19698703-e7ca-4462-aa50-5de96701bab1 for REDACTED-device/REDACTED-module <6> 2023-11-13 17:33:00.272 +00:00 [INF] - Closed cloud proxy 19698703-e7ca-4462-aa50-5de96701bab1 for REDACTED-device/REDACTED-module <6> 2023-11-13 17:33:00.277 +00:00 [INF] - Closing receiver in cloud proxy 3b22cdf4-27d1-488c-bb22-8f6eaf576c25 for REDACTED-device/$edgeHub <6> 2023-11-13 17:33:00.277 +00:00 [INF] - Closed cloud proxy 3b22cdf4-27d1-488c-bb22-8f6eaf576c25 for REDACTED-device/$edgeHub <6> 2023-11-13 17:33:00.277 +00:00 [INF] - Attempting to connect to IoT Hub for client REDACTED-device/REDACTED-module via AMQP... <6> 2023-11-13 17:33:00.277 +00:00 [INF] - Attempting to connect to IoT Hub for client REDACTED-device/$edgeHub via AMQP... <6> 2023-11-13 17:33:00.277 +00:00 [INF] - Retrying cloud proxy operation UpdateReportedPropertiesAsync for REDACTED-device/$edgeHub. Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubCloudSDKException: Operation timed out due to SDK hanging at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.<>c.<.cctor>b__43_0() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 51 at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 229 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudProxy.UpdateReportedPropertiesAsync(IMessage reportedPropertiesMessage) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudProxy.cs:line 229 at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.<>c__DisplayClass24_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 65 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 76 <4> 2023-11-13 17:34:00.286 +00:00 [WRN] - Error creating cloud connection for client REDACTED-device/$edgeHub System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session400. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session400. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 <4> 2023-11-13 17:34:00.290 +00:00 [WRN] - Error creating cloud connection for client REDACTED-device/REDACTED-module System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session401. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session401. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 <6> 2023-11-13 17:34:00.298 +00:00 [INF] - Error getting cloud connection for device REDACTED-device/$edgeHub System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session400. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session400. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 <6> 2023-11-13 17:34:00.298 +00:00 [INF] - Error getting cloud connection for device REDACTED-device/$edgeHub System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session400. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session400. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 <4> 2023-11-13 17:34:00.300 +00:00 [WRN] - Updating reported properties failed REDACTED-device/$edgeHub <6> 2023-11-13 17:34:00.299 +00:00 [INF] - Error getting cloud connection for device REDACTED-device/REDACTED-module System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session401. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session401. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 <6> 2023-11-13 17:34:00.301 +00:00 [INF] - Attempting to connect to IoT Hub for client REDACTED-device/$edgeHub via AMQP... <4> 2023-11-13 17:34:00.301 +00:00 [WRN] - Error getting twin for REDACTED-device/REDACTED-module Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubIOException: Unable to create IoTHub connection ---> System.TimeoutException: The operation timed out. ---> Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: The operation did not complete within the allocated time 00:01:00 for object session401. ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session401. at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result) at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result) at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization) --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTConnection.OpenSessionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass44_0.<b__0>d.MoveNext() --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.OpenInternalAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(Boolean withRetry, CancellationToken cancellationToken) at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Client.InternalClient.OpenAsync() at Microsoft.Azure.Devices.Edge.Util.TaskEx.TimeoutAfter(Task task, TimeSpan timeout, Action action) in /mnt/vss/_work/1/s/edge-util/src/Microsoft.Azure.Devices.Edge.Util/TaskEx.cs:line 160 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ModuleClientWrapper.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ModuleClientWrapper.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.<>c__DisplayClass30_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 196 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.InvokeFunc[T](Func`1 func, String operation, Boolean useForConnectivityCheck) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 189 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.ConnectivityAwareClient.OpenAsync() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/ConnectivityAwareClient.cs:line 65 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.ConnectToIoTHub(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 140 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.CreateNewCloudProxyAsync(ITokenProvider newTokenProvider) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 123 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnection.Create(IIdentity identity, Action`2 connectionStatusChangedHandler, ITransportSettings[] transportSettings, IMessageConverterProvider messageConverterProvider, IClientProvider clientProvider, ICloudListener cloudListener, ITokenProvider tokenProvider, TimeSpan idleTimeout, Boolean closeOnIdleTimeout, TimeSpan operationTimeout, TimeSpan cloudConnectionHangingTimeout, String productInfo, Option`1 modelId) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnection.cs:line 104 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.TryCreateCloudConnectionFromServiceIdentity(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshOutOfDateCache, CloudListener cloudListener, String authChain) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 306 at Microsoft.Azure.Devices.Edge.Hub.CloudProxy.CloudConnectionProvider.ConnectInternalWithDeviceStateTracking(IIdentity identity, Action`2 connectionStatusChangedHandler, Boolean refreshCachedIdentity) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.CloudProxy/CloudConnectionProvider.cs:line 267 --- End of inner exception stack trace --- at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.GetCloudProxy() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 120 at Microsoft.Azure.Devices.Edge.Hub.Core.Cloud.RetryingCloudProxy.ExecuteOperation[T](Func`2 func, String operation) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/cloud/RetryingCloudProxy.cs:line 73 at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.CloudSync.<>c__DisplayClass4_0.<b__0>d.MoveNext() in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/CloudSync.cs:line 40 --- End of stack trace from previous location --- at Microsoft.Azure.Devices.Edge.Hub.Core.Twin.CloudSync.GetTwin(String id) in /mnt/vss/_work/1/s/edge-hub/core/src/Microsoft.Azure.Devices.Edge.Hub.Core/twin/CloudSync.cs:line 49 <4> 2023-11-13 17:34:00.301 +00:00 [WRN] - Error calling IotHub for connectivity test Microsoft.Azure.Devices.Edge.Hub.Core.EdgeHubIOException: Unable to create IoTHub connection ```

Additional Information

In the edgeHub logs I can see the following line of which I would like to make the 00:01:00 configurable:

 ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object session401.

When I do the exact same experiment but removing the ethernet (WAN) cable from the device instead of running the iptables rules I get a slightly different result, instantiating the client takes longer but the get_twin call takes about the same amount of time:

Func create_from_edge_environment took 23.091372039998532
Func get_twin took 78.33434626300004

I have experimented with setting the on_connection_state_change callback and that appears to show that the cached twin is only retrieved when the client is marked as disconnected:

def on_connection_state_change(client: IoTHubModuleClient):
    logger.info(f"Client {'connected' if client.connected else 'disconnected'}")

How can I trigger the module client to get marked as disconnected sooner than 1min?

david-fitzgerald-re commented 1 year ago

Having found this comment https://github.com/Azure/iot-identity-service/issues/542#issuecomment-1741029534, I tried setting prefer_module_identity_cache = true in /etc/aziot/config.toml and applying the config with both sudo azioctl config apply and iotedge config apply.

This did not have any effect on the duration of the get_twin call. But it did decrease the duration of the create_from_edge_environment call when I pull the ethernet plug.

Func create_from_edge_environment took 0.037818665005033836
Func get_twin took 65.94500249600969

This doesn't solve my problem but I thought it was interesting. This does kind of beg more questions though, why there is a difference in duration of instantiating the client object with both approaches (the iptables approach and the unplugging WAN ethernet approach)

Btw the get_twin call taking 65 seconds is (I think) because I did not immediately run my python test code. The get_twin call seems to take about 80seconds from the moment I physically unplug the WAN connection.

david-fitzgerald-re commented 1 year ago

Ah, intersting, there is another configuration parameter in /etc/aziot/config.toml called cloud_timeout_sec but cannot be reduced below 70...

sudo aziotctl config apply

Caused by:
    TOML parse error at line 4, column 21
      |
    4 | cloud_timeout_sec = 10
      |                     ^^
    cloud_timeout_sec must be at least 70 seconds

Is there really no way to use a cached twin after 10 seconds?

vadim-kovalyov commented 1 year ago

Hey @david-fitzgerald-re thanks for reporting this. I'm looking into it and will update you shortly.

david-fitzgerald-re commented 12 months ago

Hey @vadim-kovalyov, any updates? 😄

vadim-kovalyov commented 12 months ago

Hey @david-fitzgerald-re sorry for slow responses, it was holiday week here in US. I'm trying to repro this issue and will update you soon.

david-fitzgerald-re commented 12 months ago

No probs @vadim-kovalyov.

If you need anything more from me to help repro please reach out.

vadim-kovalyov commented 12 months ago

Hey @david-fitzgerald-re I took some time for me to setup new env and python module (sorry, I'm not a python guy), but after all I was able to repro the issue with your steps, with exception that I used ip route add prohibit <hub_id>/32 to simulate network down in my box. Using AMQP as upstream protocol I did see the initial delay of 60+ sec for get_twin() if it coincides with the time when EdgeHub starts to notice disconnect. I'm not yet sure where that delay is coming from, trying to find out. But once EdgeHub "goes offline", the subsequent calls are timed out with CloudOperationTimeoutSecs interval, and if I update that env var I get faster timeouts (tried with 5 sec and it worked).

I brought this issue up the chain to see if this is something we can fix. But for now, I'd like to learn more about your use case to maybe suggest a workaround. Why do you call get_twin() on disconnect and why long timeout creates a problem? you should still have a previous twin (even if a bit outdated) that you can use, and fetch the new in the background.

david-fitzgerald-re commented 12 months ago

Hey @vadim-kovalyov, thanks very much for taking the time to repro! Good to know about the ip route add prohibit I might have to try that.

So with my use case, the problem is a bit of an edge case but I can describe it like so:

Assuming we have not already retrieved a twin, if my iotedge device loses internet, it will take at least 60 seconds for edgeHub to "realise" it is offline and retrieve the cached twin

For example, imagine that our device restarts whilst it has no internet, edgeHub will wait to see if it can connect to the internet for 60 seconds.

We want our device to be robust and quick to react to offline status including circumstances when the device restarts whilst offline.

This also becomes a problem in testing, because it causes the tests to wait up to 60 seconds. I had written some e2e tests to cut the net connection and see how our modules behave but realised it was blocking when retrieving the twin. I was trying to avoid mocking as much as possible, especially since these are e2e tests. It might be I have to make some allowances in this situation.

The behaviour I would like the client to exhibit could expressed like so:

twin = client.get_twin(cached=True)

or

twin = client.get_twin(timeout=5)

where, in the first example, we instantly get our cached twin, we can then start our app up instantly with that and then in the background make a blocking networked call to get_twin to the cloud whenever the net connection comes up.

and, in the second example, it would behave similarly but with some small amount of initial blocking before giving up on the net call. I think the former would be more favourable in our use case.

On the topic, do you know if it is possible (or advisable) for us to query the RocksDB ourselves? If we had an authorised query we could just get the twin ourself, though I suspect this is probably neither possible nor advisable.

vadim-kovalyov commented 12 months ago

I see. My quick answer to that problem would be to have a persistent volume for your custom module container and save your representation of twin there, so it can survive the module restart.

We can't recommend querying RocksDB directly.

As I mention in my previous comment, I observed 60+ delay only once right after EdgeHub loses connection, the subsequent calls were bounded by CloudOperationTimeoutSecs and updating it reduced the timeout. Is this the same as you observed? if so, you can reduce CloudOperationTimeoutSecs to 5 sec. But for initial 60+ second delay I don't have answer yet.

david-fitzgerald-re commented 11 months ago

@vadim-kovalyov thanks for the continued investigation, yes that is the same as we have observed.

I think we will persist our representation of the twin like you suggested. Thanks very much for your help, I think I'm happy to close this issue if you are, we will be able to work something out that fits our use case on our side.

vadim-kovalyov commented 11 months ago

Thanks @david-fitzgerald-re, I'll close this issue for now, but we will keep internal ticket open and continue investigating the 60s delay.

Azure / iotedge