DeviceClient SetMethodDefaultHandlerAsync not invoked #1409
Comments
|
Fyi, Duplicate in StackOverflow: https://stackoverflow.com/questions/62509807/deviceclient-setmethoddefaulthandlerasync-not-invoked-timely |
|
Just to clarify this issue a bit, do you mean that the ConnectionStatusChangesHandler isn't calling back in a timely manner once you sever the connection? I'm not sure I follow why you would expect the MethodDefaultHandler to call back once connection to your hub is lost |
|
The problem is not related to MethodDefaultHandler. The problem is that when my internet gets disconnected, handler associated with SetConnectionStatusChangesHandler gets triggered after 16 minutes. I should receive "disconnect" status change instantly or with in a short span of time.
The issue is why 16 minutes? why not couple of seconds? |
|
@timtay-microsoft see also some questions already asked in SO thread: https://stackoverflow.com/questions/62509807/deviceclient-setmethoddefaulthandlerasync-not-invoked-timely?noredirect=1#comment110634312_62509807 |
I posted this issue on stackoverflow |
|
Do you see similar behavior from AMQP? |
|
Yes I face same issue with AMQP |
|
We are facing the same problem when using Amqp TCP transportation. But with difference behavior between under Linux Host OS and Windows Host OS. To investigate the problem shown in our production code, we created a test program, and let it run natively under both Windows and Ubuntu. The behavior matches what we observed in our production code. The code is attached at the bottom, and is a modification from sample. Running under Windows 10 2004Network (Wi-Fi or Ethernet with actual cable) is disabled after ObservationThe log shows the IoT API call behaves as expected when OS outgoing network is disconnected and reconnectd. logsRunning under Ubuntu 18.04We simulated the network outage by enable/disable network interface. The same behavior has been observed in earlier by unplugging / plugging the network cable. Observation:
TestThe following commands are executed to disable and enable network connection usr:~$ date && sudo ifconfig eth01 down
Mon Jul 6 09:58:38 CST 2020
usr:~$ date && sudo ifconfig eth01 up
Mon Jul 6 10:00:42 CST 2020Here is the log output Testing codeThe code is attached at the bottom, and is a modification from sample. using System;
using System.Text;
using System.Threading.Tasks;
using Microsoft.Azure.Devices.Client; // 1.26.0
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Logging;
using Newtonsoft.Json;
namespace iot_hub_console
{
class Program
{
// Comandline: --DeviceConnectionString "<Actual Connection String"
static async Task Main(string[] args)
{
var accessLock = new object();
var iotStatus = ConnectionStatus.Disconnected;
var webConfig = new ConfigurationBuilder()
.AddEnvironmentVariables()
.AddCommandLine(args)
.Build();
using var loggerFactory = LoggerFactory.Create(builder => { builder.AddConsole(); });
var logger = loggerFactory.CreateLogger<Program>();
var messageId = 0;
var amqpTransportSettings = new AmqpTransportSettings(TransportType.Amqp_Tcp_Only)
{
OpenTimeout = TimeSpan.FromSeconds(60),
OperationTimeout =
TimeSpan.FromSeconds(60),
AmqpConnectionPoolSettings = new AmqpConnectionPoolSettings
{
MaxPoolSize = 3,
Pooling = true
}
};
var deviceClient = DeviceClient.CreateFromConnectionString(webConfig["DeviceConnectionString"],
new ITransportSettings[] {amqpTransportSettings});
void StatusChangedHandler(
ConnectionStatus status,
ConnectionStatusChangeReason reason)
{
lock (accessLock)
{
iotStatus = status;
}
logger.LogInformation("{0} Connection Changed to {1}, reason: {2}"
, DateTime.Now
, status
, reason);
}
deviceClient.SetConnectionStatusChangesHandler(StatusChangedHandler);
deviceClient.SetRetryPolicy(new NoRetry());
var rand = new Random();
try
{
while (true)
{
ConnectionStatus currentStatus;
lock (accessLock)
{
currentStatus = iotStatus;
}
try
{
var currentTemperature = 20 + rand.NextDouble() * 15;
var currentHumidity = 60 + rand.NextDouble() * 20;
var telemetryDataPoint = new
{
messageId = messageId++,
temperature = currentTemperature,
humidity = currentHumidity
};
var messageString = JsonConvert.SerializeObject(telemetryDataPoint);
var message = new Message(Encoding.ASCII.GetBytes(messageString));
message.Properties.Add("temperatureAlert", (currentTemperature > 30) ? "true" : "false");
await deviceClient.SendEventAsync(message);
logger.LogInformation("{0} > Sending message: {1}", DateTime.Now, messageString);
}
catch (Exception e)
{
if (currentStatus != ConnectionStatus.Connected)
{
logger.LogInformation("{0} IoT hub is not in connected status. Retry in 1 sec.",
DateTime.Now);
}
else
{
logger.LogError("{0} Sending failed with exception: {1}", DateTime.Now, e.Message);
}
}
await Task.Delay(1000);
}
}
catch (Exception e)
{
logger.LogError(e, "{0} Unhandled Exception", DateTime.Now);
}
}
}
} |
|
tag @xinchen10, since it might be related to azure-amqp |
|
To update a couple of things: the SDK is relying on the OS TCP stack to inform that the disconnect has happened, and the OS can take a couple of retries before relaying this information. This might be what is causing the connection status change handler to get invoked with a 15min delay on Linux. For Mqtt, the client does send a ping request every 75 seconds, but does not seem to be monitoring the ping response being received from the broker. I am analyzing if we should be adding this additional check for monitoring the connection status change. |
abhipsaMisra
added
the
fix-checked-in
|
I've added a fix for the mqtt layer, where the sdk now monitors for a ping response and disconnects if the delay between sending a ping request and receiving a response is >30secs (this value is currently not configurable). For the amqp implementation, the amqp library encapsulates this ping request-response logic from us; all that the device sdk does is set the |
|
@abhipsaMisra, I tested it with mqtt and it is working as expected and it resolves my issue. |
|
This fix has now been released: https://github.com/Azure/azure-iot-sdk-csharp/releases/tag/lts_2020-8-19 |
|
@timtay-microsoft, @raza707mirza, @aDisplayName, @abhipsaMisra, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey |
|
@raza707mirza please mark the answer on Stack Overflow as well. Thank you so much! https://stackoverflow.com/questions/62509807/deviceclient-setmethoddefaulthandlerasync-not-invoked-timely |
Describe the bug
DeviceClient SetMethodDefaultHandlerAsync handler is not triggered on internet disconnection instantly. It triggers after 15 to 20 minutes. Below are the logs
IoT Hub connection status Changed Status: Connected Reason: Connection_Ok Time: 3:09:15 PM +02
IoT Hub connection status Changed Status: Disconnected_Retrying Reason: Communication_Error Time: 3:26:29 PM +02
I disconnected the internet at 3:10:00 PM +02 and communication error was thrown after 16 minutes. I have created a sample code which reproduces the issue
Steps to reproduce
Expected behavior
On internet disconnection, device client should change its status in not more than 10 seconds
Actual behavior
Device client throws status change after 16 minutes
Versions used
Add following information:
dotnet --info.NET Core SDK (reflecting any global.json):
Version: 3.1.201
Commit: b1768b4ae7
Runtime Environment:
OS Name: zorin
OS Version: 15
OS Platform: Linux
RID: linux-x64
Base Path: /usr/share/dotnet/sdk/3.1.201/
Host (useful for support):
Version: 3.1.3
Commit: 4a9f85e9f8
.NET Core SDKs installed:
2.2.402 [/usr/share/dotnet/sdk]
3.1.201 [/usr/share/dotnet/sdk]
.NET Core runtimes installed:
Microsoft.AspNetCore.All 2.2.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.All]
Microsoft.AspNetCore.App 2.2.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.AspNetCore.App 3.1.3 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
Microsoft.NETCore.App 2.2.8 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
Microsoft.NETCore.App 3.1.3 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
To install additional .NET Core runtimes or SDKs:
https://aka.ms/dotnet-download
Repository is available here: https://github.com/raza707mirza/iottest
The text was updated successfully, but these errors were encountered: