[Bug Report] Code is stuck in DeviceClient.open() when withRetry argument is used and connection is not possible #1800
Description
Context
- OS and version used: Ubuntu 22.04.5 LTS
- Java runtime used: openjdk version "17.0.8" 2023-07-18
- SDK version used: 2.5.0
Description of the issue
My device's code uses the SDK reconnection mechanism with an ExponentialBackoffWithJitter retry policy.
However, due to our use case requirements, given the limited access to the device, the retry count of the policy is set to Integer.MAX_VALUE. This effectively makes the retry process last forever so that I can cover situations where the device may not have internet access for some unknown amount of time while being set up.
While performing some tests, I noticed that while first starting a connection (thus upon calling DeviceClient.open(true)), my code is stuck in this call while the SDK attempts to connect.
In the case an internet connection is not available, or the connection string is wrong, the connection will never be established, and because of my "infinite" retry policy, this method will never return unless DeviceClient.close() is called.
As the SDK documentation for the open() method mentions that it "Starts asynchronously sending and receiving messages from an IoT hub", I would imagine that the method would trigger a connection process in the backend and return, but it is not the case.
I am not completely sure, if this is indeed a bug or a mistake in the documentation, but having the SDK indeed managing the initial connection process asynchronously in the backend while the open() method returns would be more aligned with what already occurs on a reconnection process.
Thank you for your support.
Code sample exhibiting the issue
To simulate a scenario where the SDK cannot establish a connection to the cloud, I've based my tests on the device-reconnection-sample test provided with the SDK while using an invalid connection string.
However, I edited the DeviceClientManager.openDeviceClientWithRetry() method to call deviceClient.open() with a true argument instead:
private boolean openDeviceClientWithRetry() throws InterruptedException
{
while (true)
{
try
{
this.deviceClient.close();
log.debug("Attempting to open the device client");
this.deviceClient.open(true);
log.debug("Successfully opened the device client");
// region cloud to device messaging setup
// This region can be removed if no cloud to device messaging will be sent to this client
this.deviceClient.setMessageCallback(this, null);
// endregion
// region direct methods setup
// This region can be removed if no direct methods will be invoked on this client
this.deviceClient.subscribeToMethods(this, null);
// endregion
// region twin setup
// This region can be removed if no twin features will be used by this client
this.deviceClient.subscribeToDesiredProperties(this, null);
// note that this call is optional, but recommended for most scenarios. If a device is booting up for the
// first time, this call is the only way to get all the desired property updates that it missed while
// being offline. However this does send and receive bits over the wire, so it is not free.
this.twin = this.deviceClient.getTwin();
this.reportedPropertiesToSend.setVersion(twin.getReportedProperties().getVersion());
log.debug("Current twin received:");
log.debug(this.twin.toString());
// endregion
return true;
}
catch (IotHubClientException e)
{
switch (e.getStatusCode())
{
case UNAUTHORIZED:
log.error("Failed to open the device client due to incorrect or badly formatted credentials", e);
return false;
case NOT_FOUND:
log.error("Failed to open the device client because the device is not registered on your IoT Hub", e);
return false;
}
if (e.isRetryable())
{
log.debug("Failed to open the device client due to a retryable exception", e);
}
else
{
log.error("Failed to open the device client due to a non-retryable exception", e);
return false;
}
}
// Users may want to have this delay determined by an exponential backoff in order to avoid flooding the
// service with reconnect attempts. Lower delays mean a client will be reconnected sooner, but at the risk
// of wasting CPU cycles with attempts that the service is too overwhelmed to handle anyways.
log.debug("Sleeping a bit before retrying to open device client");
Thread.sleep(1000);
}
}Console log of the issue
In the attached console output, it can be seen that the DeviceClient.open() method starts at 2025-01-08 10:04:45,025 (given the "Attempting to open the device client" log message), and this call only returns when the retry policy expires, thus the connection is closed at 2025-01-08 10:08:48,664.
Connected to the target VM, address: '127.0.0.1:47733', transport: 'socket'
2025-01-08 10:04:42,507 INFO (main) [samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample] - Starting...
2025-01-08 10:04:42,511 INFO (main) [samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample] - Setup parameters...
2025-01-08 10:04:42,515 DEBUG (main) [samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample] - Setup parameter: Protocol = [mqtt]
2025-01-08 10:04:42,515 INFO (main) [samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample] - Successfully created an IoT Hub client.
2025-01-08 10:04:42,584 INFO (main) [com.microsoft.azure.sdk.iot.device.transport.ExponentialBackoffWithJitter] - NOTE: A new instance of ExponentialBackoffWithJitter has been created with the following properties. Retry Count: 2147483647, Min Backoff Interval: 100, Max Backoff Interval: 10000, Max Time Between Retries: 100, Fast Retry Enabled: true
2025-01-08 10:04:42,768 DEBUG (main) [com.microsoft.azure.sdk.iot.device.ClientConfiguration] - Device configured to use software based SAS authentication provider
2025-01-08 10:04:42,781 DEBUG (main) [com.microsoft.azure.sdk.iot.device.DeviceClient] - Initialized a DeviceClient instance using SDK version 2.5.0
2025-01-08 10:04:42,781 INFO (main) [samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample] - Starting IoT Hub client...
2025-01-08 10:04:42,782 INFO (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.DeviceClient] - Closing device client...
2025-01-08 10:04:42,782 INFO (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.DeviceClient] - Device client closed successfully
2025-01-08 10:04:45,025 DEBUG (Iot-Hub-Connection-Manager-Thread) [samples.com.microsoft.azure.sdk.iot.DeviceClientManager] - Attempting to open the device client
2025-01-08 10:04:45,903 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection] - Opening MQTT connection...
2025-01-08 10:04:45,939 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Sending MQTT CONNECT packet...
2025-01-08 10:04:47,517 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Exception encountered while sending MQTT CONNECT packet
org.eclipse.paho.client.mqttv3.MqttSecurityException: Not authorized to connect
at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:28) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.ClientState.notifyReceivedAck(ClientState.java:1053) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:151) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at java.lang.Thread.run(Thread.java:840) ~[?:?]
2025-01-08 10:04:47,522 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.IotHubTransport] - Encountered an exception while opening the client. Checking the configured retry policy to see if another attempt should be made.
com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.MqttUnauthorizedException: Unable to establish MQTT connection
at com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.PahoExceptionTranslator.convertToMqttException(PahoExceptionTranslator.java:53) ~[classes/:?]
at com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt.connect(Mqtt.java:132) ~[classes/:?]
at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttMessaging.start(MqttMessaging.java:62) ~[classes/:?]
at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.open(MqttIotHubConnection.java:286) ~[classes/:?]
at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.openConnection(IotHubTransport.java:1415) ~[classes/:?]
at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.open(IotHubTransport.java:506) [classes/:?]
at com.microsoft.azure.sdk.iot.device.DeviceIO.open(DeviceIO.java:119) [classes/:?]
at com.microsoft.azure.sdk.iot.device.InternalClient.open(InternalClient.java:163) [classes/:?]
at com.microsoft.azure.sdk.iot.device.DeviceClient.open(DeviceClient.java:201) [classes/:?]
at samples.com.microsoft.azure.sdk.iot.DeviceClientManager.openDeviceClientWithRetry(DeviceClientManager.java:168) [classes/:?]
at samples.com.microsoft.azure.sdk.iot.DeviceClientManager.run(DeviceClientManager.java:116) [classes/:?]
at samples.com.microsoft.azure.sdk.iot.DeviceClientManagerSample.main(DeviceClientManagerSample.java:62) [classes/:?]
Caused by: org.eclipse.paho.client.mqttv3.MqttSecurityException: Not authorized to connect
at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:28) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.ClientState.notifyReceivedAck(ClientState.java:1053) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:151) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at java.lang.Thread.run(Thread.java:840) ~[?:?]
2025-01-08 10:04:47,523 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.RetryDecision] - NOTE: A new instance of RetryDecision has been created with retry enabled, the client will retry after 0 milliseconds
2025-01-08 10:04:47,523 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection] - Opening MQTT connection...
2025-01-08 10:04:47,523 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Sending MQTT CONNECT packet...
2025-01-08 10:04:48,817 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Exception encountered while sending MQTT CONNECT packet
org.eclipse.paho.client.mqttv3.MqttSecurityException: Not authorized to connect
=== Ommited multiple retries ===
2025-01-08 10:08:47,664 DEBUG (Iot-Hub-Connection-Manager-Thread) [samples.com.microsoft.azure.sdk.iot.DeviceClientManager] - Sleeping a bit before retrying to open device client
2025-01-08 10:08:48,664 INFO (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.DeviceClient] - Closing device client...
2025-01-08 10:08:48,665 INFO (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.DeviceClient] - Device client closed successfully
2025-01-08 10:08:49,008 DEBUG (Iot-Hub-Connection-Manager-Thread) [samples.com.microsoft.azure.sdk.iot.DeviceClientManager] - Attempting to open the device client
2025-01-08 10:08:49,636 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection] - Opening MQTT connection...
2025-01-08 10:08:49,637 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Sending MQTT CONNECT packet...
2025-01-08 10:08:52,179 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.mqtt.Mqtt] - Exception encountered while sending MQTT CONNECT packet
org.eclipse.paho.client.mqttv3.MqttSecurityException: Not authorized to connect
at org.eclipse.paho.client.mqttv3.internal.ExceptionHelper.createMqttException(ExceptionHelper.java:28) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.ClientState.notifyReceivedAck(ClientState.java:1053) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:151) ~[org.eclipse.paho.client.mqttv3-1.2.5.jar:?]
at java.lang.Thread.run(Thread.java:840) ~[?:?]
2025-01-08 10:08:52,180 DEBUG (Iot-Hub-Connection-Manager-Thread) [com.microsoft.azure.sdk.iot.device.transport.IotHubTransport] - Encountered an exception while opening the client. Checking the configured retry policy to see if another attempt should be made.
com.microsoft.azure.sdk.iot.device.transport.mqtt.exceptions.MqttUnauthorizedException: Unable to establish MQTT connection