Open mawax opened 2 years ago
Hi, thank you for the report and detailed repro steps. I have replicated the issue. A bug has been filed and we're investigating solutions.
This issue is being marked as stale because it has been open for 30 days with no activity.
@mawax hey, we're still looking into this bug. Hopefully we'll have an update next week
@mawax we're still investigating. In the meantime can you let us know if this is blocking you at all?
This is currently no longer blocking for us, we changed our implementation so that we are no longer dependent on reported properties.
Still an issue with 1.4.32. Please we aware that GetTwinAsync is subject to the same problem.
Expected Behavior
Updating reported properties with
ModuleClient.UpdateReportedPropertiesAsync
when the device is offline should return fast.Current Behavior
Updating reported properties with
ModuleClient.UpdateReportedPropertiesAsync
when the device is offline will periodically take 20 seconds (depends on the value ofCloudOperationTimeoutSecs
). When the timeout is triggered by callingUpdateReportedPropertiesAsync
all method calls toSendEventAsync
will also wait for the timeout to pass.Steps to Reproduce
UpdateReportedPropertiesAsync
on the ModuleClientUpdateReportedPropertiesAsync
again.UpdateReportedPropertiesAsync
will be fast for 5 seconds (depending on the environment variableReportedPropertiesSyncFrequencySecs
). Then it will take 20 seconds again.I have supplied a sample app where the behaviour can be reproduced:
Full code here: https://github.com/mawax/iotedge-issue-demo/blob/main/OfflineModule/Program.cs
Output:
Context (Environment)
Output of
iotedge check
Click here
``` PS C:\Windows\system32> iotedge check Configuration checks -------------------- √ config.yaml is well-formed - OK √ config.yaml has well-formed connection string - OK √ container engine is installed and functional - OK √ Windows host version is supported - OK √ config.yaml has correct hostname - OK √ config.yaml has correct URIs for daemon mgmt endpoint - OK ‼ latest security daemon - Warning Installed IoT Edge daemon has version 1.1.8 but 1.1.9 is the latest stable version available. Please see https://aka.ms/iotedge-update-runtime for update instructions. √ host time is close to real time - OK √ container time is close to host time - OK √ DNS server - OK ‼ production readiness: certificates - Warning The Edge device is using self-signed automatically-generated development certificates. They will expire in 41 days (at 2022-04-04 15:47:28 UTC) causing module-to-module and downstream device communication to fail on an active deployment. After the certs have expired, restarting the IoT Edge daemon will trigger it to generate new development certs. Please consider using production certificates instead. See https://aka.ms/iotedge-prod-checklist-certs for best practices. √ production readiness: container engine - OK √ production readiness: logs policy - OK ‼ production readiness: Edge Agent's storage directory is persisted on the host filesystem - Warning The edgeAgent module is not configured to persist its C:\rEdge\edgeAgent directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. ‼ production readiness: Edge Hub's storage directory is persisted on the host filesystem - Warning The edgeHub module is not configured to persist its C:\rEdge\edgeHub directory on the host filesystem. Data might be lost if the module is deleted or updated. Please see https://aka.ms/iotedge-storage-host for best practices. Connectivity checks ------------------- √ host can connect to and perform TLS handshake with IoT Hub AMQP port - OK √ host can connect to and perform TLS handshake with IoT Hub HTTPS / WebSockets port - OK √ host can connect to and perform TLS handshake with IoT Hub MQTT port - OK √ container on the IoT Edge module network can connect to IoT Hub AMQP port - OK √ container on the IoT Edge module network can connect to IoT Hub HTTPS / WebSockets port - OK √ container on the IoT Edge module network can connect to IoT Hub MQTT port - OK 17 check(s) succeeded. 4 check(s) raised warnings. Re-run with --verbose for more details. ```Device Information
Runtime Versions
iotedge version
]: iotedge 1.1.8 (54b31809c98ee83e36679ecf92c5582de37172c4)docker version
]: 19.03.12+azureNote: when using Windows containers on Windows, run
docker -H npipe:////./pipe/iotedge_moby_engine version
insteadLogs
edgeHubDev mcr.microsoft.com/azureiotedge-hub:1.2 logs
``` 2022-02-21 16:31:55 Starting Edge Hub Feb 21 16:31:55.512 INFO watchdog: Starting Watchdog Feb 21 16:31:55.512 INFO watchdog: Registering shutdown signal listener Feb 21 16:31:55.513 INFO watchdog: MQTT broker is disabled Feb 21 16:31:55.513 INFO watchdog::child: Launched Edge Hub process with pid 10 2022-02-21 16:31:55.587 +00:00 Edge Hub Main() <6> 2022-02-21 16:31:55.809 +00:00 [INF] - Installing certificates [CN=Edge Agent CA, OU=Default Edge Organization, O=Default Edge Organization, L=Redmond, S=Washington, C=US:12/27/2022 13:57:42],[CN=Edge Test Device CA, OU=Default Edge Organization, O=Default Edge Organization, L=Redmond, S=Washington, C=US:12/28/2022 13:57:36] to Root <6> 2022-02-21 16:31:55.838 +00:00 [INF] - Installing certificates to Root <6> 2022-02-21 16:31:55.841 +00:00 [INF] - Enabling SSL protocols: Tls, Tls11, Tls12 <6> 2022-02-21 16:31:56.126 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2022-02-21 16:31:56.456 +00:00 [INF] - Created persistent store at /tmp/edgeHub <6> 2022-02-21 16:31:56.468 +00:00 [INF] - Created device scope identities cache <6> 2022-02-21 16:31:56.474 +00:00 [INF] - Starting refresh of device scope identities cache <6> 2022-02-21 16:31:56.486 +00:00 [INF] - Initializing Edge Hub <6> 2022-02-21 16:31:56.486 +00:00 [INF] - █████╗ ███████╗██╗ ██╗██████╗ ███████╗ ██╔══██╗╚══███╔╝██║ ██║██╔══██╗██╔════╝ ███████║ ███╔╝ ██║ ██║██████╔╝█████╗ ██╔══██║ ███╔╝ ██║ ██║██╔══██╗██╔══╝ ██║ ██║███████╗╚██████╔╝██║ ██║███████╗ ╚═╝ ╚═╝╚══════╝ ╚═════╝ ╚═╝ ╚═╝╚══════╝ ██╗ ██████╗ ████████╗ ███████╗██████╗ ██████╗ ███████╗ ██║██╔═══██╗╚══██╔══╝ ██╔════╝██╔══██╗██╔════╝ ██╔════╝ ██║██║ ██║ ██║ █████╗ ██║ ██║██║ ███╗█████╗ ██║██║ ██║ ██║ ██╔══╝ ██║ ██║██║ ██║██╔══╝ ██║╚██████╔╝ ██║ ███████╗██████╔╝╚██████╔╝███████╗ ╚═╝ ╚═════╝ ╚═╝ ╚══════╝╚═════╝ ╚═════╝ ╚══════╝ <6> 2022-02-21 16:31:56.487 +00:00 [INF] - Version - 1.2.7.50979330 (d3ec971caa0af0fc39d2c1f91aef21e95bd0c03c) <6> 2022-02-21 16:31:56.487 +00:00 [INF] - OptimizeForPerformance=True <6> 2022-02-21 16:31:56.488 +00:00 [INF] - MessageAckTimeoutSecs=30 <6> 2022-02-21 16:31:56.489 +00:00 [INF] - Loaded server certificate with expiration date of "2022-12-26T13:57:42.0000000+00:00" <6> 2022-02-21 16:31:56.494 +00:00 [INF] - Using Asp Net server for metrics <6> 2022-02-21 16:31:56.518 +00:00 [INF] - Created new message store <6> 2022-02-21 16:31:56.519 +00:00 [INF] - Started task to cleanup processed and stale messages <6> 2022-02-21 16:31:56.587 +00:00 [INF] - Created DeviceConnectivityManager with connected check frequency 00:05:00 and disconnected check frequency 00:02:00 <6> 2022-02-21 16:31:56.611 +00:00 [INF] - Initialized storing twin manager <6> 2022-02-21 16:31:56.622 +00:00 [INF] - Add node: IoT-Device-MW-LocalDev/$edgeHub <6> 2022-02-21 16:31:56.622 +00:00 [INF] - Initializing configuration <6> 2022-02-21 16:31:56.736 +00:00 [INF] - Created cloud endpoint iothub with max batch size 10 and fan-out factor of 10. <6> 2022-02-21 16:31:56.739 +00:00 [INF] - Experimental features configuration: {"Enabled":false,"DisableCloudSubscriptions":false,"DisableConnectivityCheck":false,"EnableMqttBroker":false} <6> 2022-02-21 16:31:56.793 +00:00 [INF] - Starting timer to authenticate connections with a period of 300 seconds <6> 2022-02-21 16:31:56.828 +00:00 [INF] - Set the following 1 route(s) in edge hub <6> 2022-02-21 16:31:56.828 +00:00 [INF] - r1: FROM /* INTO $upstream <6> 2022-02-21 16:31:56.829 +00:00 [INF] - Updated message store TTL to 922337203685.4775 seconds <6> 2022-02-21 16:31:56.829 +00:00 [INF] - Updated the edge hub store and forward configuration <6> 2022-02-21 16:31:56.834 +00:00 [INF] - Started operation Get EdgeHub config <6> 2022-02-21 16:31:56.834 +00:00 [INF] - Initialized edge hub configuration <6> 2022-02-21 16:31:56.835 +00:00 [INF] - Scheduling server certificate renewal for "2022-12-26T13:55:12.0000565Z". <6> 2022-02-21 16:31:56.836 +00:00 [INF] - Starting protocol heads - (MQTT, AMQP, HTTP) <6> 2022-02-21 16:31:56.837 +00:00 [INF] - Starting MQTT head <6> 2022-02-21 16:31:56.865 +00:00 [INF] - Initializing TLS endpoint on port 8883 for MQTT head. <6> 2022-02-21 16:31:56.899 +00:00 [INF] - Starting AMQP head <6> 2022-02-21 16:31:56.905 +00:00 [INF] - Started MQTT head <6> 2022-02-21 16:31:56.953 +00:00 [INF] - Started AMQP head <6> 2022-02-21 16:31:56.954 +00:00 [INF] - Starting HTTP head <4> 2022-02-21 16:31:57.079 +00:00 [WRN] - Overriding address(es) '"http://+:80"'. Binding to endpoints defined in "UseKestrel()" instead. <6> 2022-02-21 16:31:57.083 +00:00 [INF] - Started HTTP head <4> 2022-02-21 16:31:57.251 +00:00 [WRN] - TLS handshake failed., System.IO.IOException: Channel is closed, 076e641d <6> 2022-02-21 16:31:58.060 +00:00 [INF] - Add node: IoT-Device-MW-LocalDev <6> 2022-02-21 16:31:58.083 +00:00 [INF] - Add node: IoT-Device-MW-LocalDev/$edgeAgent <6> 2022-02-21 16:31:58.086 +00:00 [INF] - Updated node: IoT-Device-MW-LocalDev/$edgeHub <6> 2022-02-21 16:31:58.087 +00:00 [INF] - Service identity for IoT-Device-MW-LocalDev/$edgeHub in device scope was updated. <6> 2022-02-21 16:31:58.089 +00:00 [INF] - Add node: IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:31:58.092 +00:00 [INF] - Done refreshing device scope identities cache. Waiting for 60 minutes. <6> 2022-02-21 16:32:00.932 +00:00 [INF] - Client IoT-Device-MW-LocalDev/OfflineModule in device scope authenticated locally. <6> 2022-02-21 16:32:00.950 +00:00 [INF] - Successfully generated identity for clientId IoT-Device-MW-LocalDev/OfflineModule and username localhost/IoT-Device-MW-LocalDev/OfflineModule/?api-version=2020-09-30&DeviceClientType=.NET%2F1.40.0%20%28.NET%206.0.2%3B%20Microsoft%20Windows%2010.0.19043%20WindowsProduct%3A0x00000030%3B%20X64%3B%20%7B5CCDF86B-277F-4A5C-9481-21A4B56427D1%7D%29 <6> 2022-02-21 16:32:00.951 +00:00 [INF] - ClientAuthenticated, IoT-Device-MW-LocalDev/OfflineModule, 49045fd6 <6> 2022-02-21 16:32:00.970 +00:00 [INF] - New device connection for device IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:00.974 +00:00 [INF] - Client IoT-Device-MW-LocalDev/OfflineModule connected to edgeHub, processing existing subscriptions. <6> 2022-02-21 16:32:01.001 +00:00 [INF] - Bind device proxy for device IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.002 +00:00 [INF] - Binding message channel for device Id IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.019 +00:00 [INF] - Processing subscriptions TwinResponse for client IoT-Device-MW-LocalDev/OfflineModule. <6> 2022-02-21 16:32:01.026 +00:00 [INF] - Processing pending subscriptions for IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.043 +00:00 [INF] - Attempting to connect to IoT Hub for client IoT-Device-MW-LocalDev/OfflineModule via AMQP... <6> 2022-02-21 16:32:01.111 +00:00 [INF] - Set subscriptions from session state for IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.506 +00:00 [INF] - Exiting disconnected state <6> 2022-02-21 16:32:01.517 +00:00 [INF] - Received device connected callback <6> 2022-02-21 16:32:01.521 +00:00 [INF] - Device connected to cloud, processing subscriptions for connected clients. <6> 2022-02-21 16:32:01.522 +00:00 [INF] - Processing subscriptions for client IoT-Device-MW-LocalDev/OfflineModule on device connected to cloud. <6> 2022-02-21 16:32:01.522 +00:00 [INF] - Skipping IoT-Device-MW-LocalDev/OfflineModule for subscription processing, as it is currently being processed. <6> 2022-02-21 16:32:01.523 +00:00 [INF] - Skipping cache refresh, waiting 116 seconds until refreshing again. <6> 2022-02-21 16:32:01.529 +00:00 [INF] - Entering connected state <6> 2022-02-21 16:32:01.531 +00:00 [INF] - Cloud connection for IoT-Device-MW-LocalDev/OfflineModule is True <6> 2022-02-21 16:32:01.533 +00:00 [INF] - Connection status for IoT-Device-MW-LocalDev/OfflineModule changed to ConnectionEstablished <6> 2022-02-21 16:32:01.534 +00:00 [INF] - Client IoT-Device-MW-LocalDev/OfflineModule connected to cloud, processing existing subscriptions. <6> 2022-02-21 16:32:01.535 +00:00 [INF] - Skipping IoT-Device-MW-LocalDev/OfflineModule for subscription processing, as it is currently being processed. <6> 2022-02-21 16:32:01.536 +00:00 [INF] - Created cloud proxy for client IoT-Device-MW-LocalDev/OfflineModule via AMQP, with client operation timeout 20 seconds. <6> 2022-02-21 16:32:01.538 +00:00 [INF] - Initialized cloud proxy 3ef72f2d-c5da-4bce-a8c8-ac6de4285c5e for IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.539 +00:00 [INF] - Created cloud connection for client IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:01.552 +00:00 [INF] - Done syncing reported properties for IoT-Device-MW-LocalDev/OfflineModule <6> 2022-02-21 16:32:23.872 +00:00 [INF] - Attempting to connect to IoT Hub for client IoT-Device-MW-LocalDev/$edgeHub via AMQP... <6> 2022-02-21 16:32:43.815 +00:00 [INF] - Exiting connected state <6> 2022-02-21 16:32:43.816 +00:00 [INF] - Entering unreachable state <4> 2022-02-21 16:32:43.825 +00:00 [WRN] - Updating reported properties failed IoT-Device-MW-LocalDev/OfflineModule <4> 2022-02-21 16:32:50.697 +00:00 [WRN] - Error creating cloud connection for client IoT-Device-MW-LocalDev/$edgeHub Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> System.Net.Sockets.SocketException (0xFFFDFFFF): Name does not resolve at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.InitializeAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpIoTConnector.OpenConnectionAsync(TimeSpan timeout) at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.EnsureConnectionAsync(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.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.<Additional Information
Issue occurs both with Linux and Windows Containers and using the edgeHubDev or actual device.