Azure-iot-sdk-csharp: Default RetryPolicy is broken

[dmytro-gokun]

Microsoft.Azure.Devices.Client, Version=1.21.1.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35

In my app, i've implemented LoggingRetryPolicy, so that i can monitor how the default ExponentialBackoff policy performs. Here's the code:

        private class LoggingRetryPolicy : IRetryPolicy
        {
            private readonly IRetryPolicy _policy;

            public LoggingRetryPolicy(IRetryPolicy policy)
            {
                _policy = policy;
            }

            public bool ShouldRetry(int currentRetryCount, Exception lastException, out TimeSpan retryInterval)
            {
                var result = _policy.ShouldRetry(currentRetryCount, lastException, out retryInterval);
                if (result)
                    Log.Warn(lastException, "Retrying. CurrentRetryCount: {0}, RetryInterval: {1}", currentRetryCount, retryInterval);
                return result;
            }
        }

So, nothing special here, just logging the current retry count & delay.
And here's how i use it:

var deviceClient = DeviceClient.Create(...);
// This is the default retry policy according to the docs.
var defaultRetryPolicy = new ExponentialBackoff(int.MaxValue, TimeSpan.FromMilliseconds(100), TimeSpan.FromSeconds(10), TimeSpan.FromMilliseconds(100));
deviceClient.SetRetryPolicy(new LoggingRetryPolicy(defaultRetryPolicy));

And then i do bunch of theses whenever needed:

await deviceClient.SendEventAsync(message, cancellationToken);

So far, so good. Mostly this works just fine. In fact it worked perfectly (for many months) until the last night. And here is the log from the last night:

2019-10-07T02:02:36.8839Z Retrying. CurrentRetryCount: 0, RetryInterval: 00:00:00.1000000
2019-10-07T02:02:37.8372Z Retrying. CurrentRetryCount: 1, RetryInterval: 00:00:00.2130000
...
2019-10-07T02:02:47.0596Z Retrying. CurrentRetryCount: 6, RetryInterval: 00:00:06.0850000
2019-10-07T02:02:53.1893Z Retrying. CurrentRetryCount: 7, RetryInterval: 00:00:10
...
2019-10-07T02:06:00.9973Z Retrying. CurrentRetryCount: 24, RetryInterval: 00:00:10
... and BOOM:
2019-10-07T02:06:13.4982Z Retrying. CurrentRetryCount: 25, RetryInterval: -24.20:31:23.5480000
... and then it goes like that forever:
2019-10-07T02:06:14.8231Z Retrying. CurrentRetryCount: 26, RetryInterval: -24.20:31:23.5480000
...
2019-10-07T02:39:22.8101Z Retrying. CurrentRetryCount: 350, RetryInterval: -24.20:31:23.5480000

Another interesting thing: exception alternate. So, first i see this one:

Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> System.Net.Sockets.SocketException: An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full
   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.EnsureSessionAsync(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__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   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__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext(){""Type"":""Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException"", ""IsTransient"":true, ""TrackingId"":"""", ""Message"":""Transient network error occurred, please retry."", ""Data"":{}, ""InnerException"":{""Type"":""System.Net.Sockets.SocketException"", ""Message"":""An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full"", ""SocketErrorCode"":""NoBufferSpaceAvailable"", ""ErrorCode"":10055, ""NativeErrorCode"":10055, ""Data"":{}, ""TargetSite"":""Void Throw()"", ""StackTrace"":""   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.InitializeAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpIoTConnector.OpenConnectionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.EnsureConnectionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)\r\n   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)\r\n   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)"", ""Source"":""System.Private.CoreLib"", ""HResult"":-2147467259}, ""TargetSite"":""Void MoveNext()"", ""StackTrace"":""   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)\r\n   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()"", ""Source"":""Microsoft.Azure.Devices.Client"", ""HResult"":-2146233088}"

then this one:

Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> System.Net.WebSockets.WebSocketException: Unable to connect to the remote server ---> System.Net.Http.HttpRequestException: An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full ---> System.Net.Sockets.SocketException: An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at System.Net.Http.HttpConnectionPool.CreateConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at System.Net.Http.HttpConnectionPool.WaitForCreatedConnectionAsync(ValueTask`1 creationTask)
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.WebSockets.WebSocketHandle.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken, ClientWebSocketOptions options)
   --- End of inner exception stack trace ---
   at System.Net.WebSockets.WebSocketHandle.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken, ClientWebSocketOptions options)
   at System.Net.WebSockets.ClientWebSocket.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.CreateClientWebSocketAsync(Uri websocketUri, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.CreateClientWebSocketTransportAsync(TimeSpan timeout)
   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.EnsureSessionAsync(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__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   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__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext(){""Type"":""Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException"", ""IsTransient"":true, ""TrackingId"":"""", ""Message"":""Transient network error occurred, please retry."", ""Data"":{}, ""InnerException"":{""Type"":""System.Net.WebSockets.WebSocketException"", ""ErrorCode"":0, ""WebSocketErrorCode"":""Success"", ""NativeErrorCode"":0, ""Message"":""Unable to connect to the remote server"", ""Data"":{}, ""InnerException"":{""Type"":""System.Net.Http.HttpRequestException"", ""Message"":""An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full"", ""Data"":{}, ""InnerException"":{""Type"":""System.Net.Sockets.SocketException"", ""Message"":""An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full"", ""SocketErrorCode"":""NoBufferSpaceAvailable"", ""ErrorCode"":10055, ""NativeErrorCode"":10055, ""Data"":{}, ""TargetSite"":""Void Throw()"", ""StackTrace"":""   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)"", ""Source"":""System.Private.CoreLib"", ""HResult"":-2147467259}, ""TargetSite"":""Void MoveNext()"", ""StackTrace"":""   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)\r\n   at System.Threading.Tasks.ValueTask`1.get_Result()\r\n   at System.Net.Http.HttpConnectionPool.CreateConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n   at System.Threading.Tasks.ValueTask`1.get_Result()\r\n   at System.Net.Http.HttpConnectionPool.WaitForCreatedConnectionAsync(ValueTask`1 creationTask)\r\n   at System.Threading.Tasks.ValueTask`1.get_Result()\r\n   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)\r\n   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)\r\n   at System.Net.WebSockets.WebSocketHandle.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken, ClientWebSocketOptions options)"", ""Source"":""System.Net.Http"", ""HResult"":-2147467259}, ""TargetSite"":""Void MoveNext()"", ""StackTrace"":""   at System.Net.WebSockets.WebSocketHandle.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken, ClientWebSocketOptions options)\r\n   at System.Net.WebSockets.ClientWebSocket.ConnectAsyncCore(Uri uri, CancellationToken cancellationToken)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.CreateClientWebSocketAsync(Uri websocketUri, TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.CreateClientWebSocketTransportAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpIoTTransport.InitializeAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpIoTConnector.OpenConnectionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.EnsureConnectionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)\r\n   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)\r\n   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)\r\n   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass22_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)"", ""Source"":""System.Net.WebSockets.Client"", ""HResult"":-2147467259}, ""TargetSite"":""Void MoveNext()"", ""StackTrace"":""   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)\r\n   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass32_0.<<OpenAsyncInternal>b__0>d.MoveNext()"", ""Source"":""Microsoft.Azure.Devices.Client"", ""HResult"":-2146233088}"

and after that they continue alternating.

A couple more notes here: my app is a custom gateway. So, I have thousands of connections doing this thing at the same time. Also, there is a timeout (several minutes) after which _cancellationToken_ is canceled. I would then expect this retry madness to stop. However, it never did. As soon as i restarted the service, everything went back to normal.

[dmytro-gokun]

UPDATE: after examining my code, i have found that in this case my _cancellationToken_ was not actually canceled. So, at least no problem with that. However, I'd expect DeviceClient.DefaultOperationTimeoutInMilliseconds (240s) to kick in this case, but it did not, as can be seen from timestamps in the log.

[timtay-microsoft]

The negative RetryInterval that you noticed is a duplicate of #969 and we do have a fix in the works for it.

Just to clarify, you don't have any issues with the cancellation token being respected during retry, correct?

As for the Exception

Microsoft.Azure.Devices.Client.Exceptions.IotHubCommunicationException: Transient network error occurred, please retry. ---> ... ---> System.Net.Sockets.SocketException: An operation on a socket could not be performed because the system lacked sufficient buffer space or because a queue was full

This is likely a duplicate of issue #1098 which we are still investigating.

[dmytro-gokun]

Just to clarify, you don't have any issues with the cancellation token being respected during retry, correct?

No, there is no issue with that as i've said in this comment: https://github.com/Azure/azure-iot-sdk-csharp/issues/1081#issuecomment-539088860

But DeviceClient.DefaultOperationTimeoutInMilliseconds (240s) is not kicking in.

This is likely a duplicate of issue #1098 which we are still investigating.

Well, #1098 was created 23 hrs ago and this one 23 days ago, so i'd argue that one is a duplicate :) Joking aside... this just needs to be fixed soon, as i've already seen happening it again the other day.

[timtay-microsoft]

On the device operation timeout issue, there is a fundamental difference between these two calls

await client.sendEventAsync(message);
await client.sendEventAsync(message, someCancellationToken);

When you provide a cancellation token to the API, the SDK will ignore the device operation timeout and instead rely on your cancellation token to tell the retry to stop.

In your case, it seems you are passing a cancellation token to the sendEventAsync(...) call so that is why the device operation timeout doesn't stop the retry.

Note that you can still mix operations with and without a custom timeout.

await client.sendEventAsync(message); //Will use device operation timeout
await client.sendEventAsync(message, someCancellationToken); //Will not use device operation timeout
await client.sendEventAsync(message); //Will use device operation timeout

The same applies to all other client APIs where a cancellation token is an option, such as openAsync()

[dmytro-gokun]

Okay, that explains why there is no timeout. I would not say it is intuitively expected behavior though. If it's how this is designed to work and not a bug, it has be documented (or may be it is and i somehow missed that?).

[timtay-microsoft]

I agree that this is not intuitive behavior, but it is by design. It wouldn't make sense to accept a cancellation token but to have the device operation timeout take precedence if the device operation timeout occurs before the token is cancelled.

We'll take it on ourselves to make sure this gets properly documented, though

[timtay-microsoft]

Just to update this thread on the last issue you reported here (leaked sockets), it looks like the 1.21.1 device client does not properly close AMQP sockets during exceptional cases. We have a PR in the works to fix this issue here

Most of the discussion around this issue is happening within #1098, if you want to follow it or add your findings

[dmytro-gokun]

Closing this as it should have been fixed in Microsoft.Azure.Devices.Client v1.21.2

[az-iot-builder-01]

@dmytro-gokun, thank you for your contribution to our open-sourced project! Please help us improve by filling out this 2-minute customer satisfaction survey

[timtay-microsoft]

Just to clarify this thread, 1.21.2 should contain fixes for the leaked sockets issue and the retry policy underflow issue.