Azure-iot-sdk-csharp: DeviceClient.GetTwinAsync throws KeyNotFoundException

[dmytro-gokun]

Hi,

I'm using Microsoft.Azure.Devices.Client.dll, version 1.6.2

Sometimes DeviceClient.GetTwinAsync throws KeyNotFoundException. When called second time, the exception disappears and everything seems to work as expected (or, at least, I think so).

System.Collections.Generic.KeyNotFoundException: The given key was not present in the dictionary.
at Microsoft.Azure.Devices.Client.DeviceClient.<>c.b__75_2(Task1 t) at System.Threading.Tasks.ContinuationResultTaskFromResultTask2.InnerInvoke()
at System.Threading.Tasks.Task.Execute()

Any help is appreciated.

Dmytro.

[CIPop]

Thanks for reporting @dmytro-gokun ! We'll need to take a look.
@zolvarga PTAL

[zolvarga]

@dmytro-gokun

Could you please provide the sample code you executed?

Thanks,
Zoltan

[zolvarga]

@dmytro-gokun

I don't have a repro using this code:

            try
            {
                for (int i = 0; i < 1000; i++)
                {
                    Twin tw = await client.GetTwinAsync();
                    Console.Write(".");
                }
            }
            catch (Exception e)
            {
                Console.WriteLine("Exception: " + e.ToString());
            }

Could you also specify the hardware you are running the code on?

Best Regards,
Zoltan

[dmytro-gokun]

Well, there is nothing special about the hardware. In fact, our software is a gateway for a proprietary protocol, so it's a cloud service running on WindowsAzureGuestOS5.15 (targeting .NET 4.7.1). At the end of the day, its some Intel-based Azure hardware owned by MS.

About your code ... where is your "client" variable is coming from? In our case we do something like this ("_connectionString" is IoT Hub connection string which comes from the config):

1) We receive "deviceId" from the proprietary protocol's "connect" message;
2) Then we obtain the "Device" object like this:

var registryManager = RegistryManager.CreateFromConnectionString(_connectionString); var device = await registryManager.GetDeviceAsync(deviceId);

3) Then we create the "DeviceClient" like this:

var iotHubUri = IotHubConnectionStringBuilder.Create(_connectionString).HostName; var deviceClient = DeviceClient.Create(iotHubUri, new DeviceAuthenticationWithRegistrySymmetricKey(device.Id, device.Authentication.SymmetricKey.PrimaryKey));

Please let me know if you need some more info.

[zolvarga]

@dmytro-gokun

In my case I had an existing device and got the connection string for it.
I reated the client from the connection string using the following constructor:
var client = DeviceClient.CreateFromConnectionString(...)

I will investigate this issue further.

Best Regards,
Zoltan

[dmytro-gokun]

@zolvarga Another idea: i think it only happens the very first time GetTwinAsync called. So, you have better chance reproducing, if you create a fresh Device ID with a pristine, untouched twin.

[dmytro-gokun]

@zolvarga I've now analyzed our service logs, so plz ignore my previous comment, as it contains a wrong assumption. So here's what I've found:

1) During last 2 weeks it happened 3 times;
2) Every time it happened, it happened after the service restart, to the VERY first call to GetTwinAsync. All the following calls were successful;
3) Every time it happened to a different device. Whatever device was first to connect to the service after a restart - that was the victim.

So, i think it's some kind of a library initialization issue.

Another clue: when a device connects, we start two async tasks in parallel (using same instance of DeviceClient):

1) desired/reported property synchronizer. This is the task that calls GetTwinAsync;
2) cloud to device message sender. This task calls ReceiveAsync in the loop.

Could it be that GetTwinAsync/ReceiveAsync called on the same instance of DeviceClient produce a problem? I've looked through DeviceClient docs and cannot see any indication on the fact if it's allowed to call its async methods in parallel or not.

[yfakariya]

Hi, I also faced same problem. I hooked AppDomain.FirstChanceException event (as MYLAMBDA_FUNCTION bellow stack trace) and I saw following callstack via Environment.StackTrace in the event handler:

System.Collections.Generic.KeyNotFoundException: The given key was not present in the dictionary.
   at System.Environment.get_StackTrace()
   at MYLAMBDA_FUNCTION(Object sender, FirstChanceExceptionEventArgs e)
   at System.Collections.Concurrent.ConcurrentDictionary`2.ThrowKeyNotFoundException()
   at System.Collections.Concurrent.ConcurrentDictionary`2.get_Item(TKey key)
   at Microsoft.Azure.Devices.Client.Transport.AmqpTransportHandler.<RoundTripTwinMessage>d__56.MoveNext()
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

I think above callstack suggests:

• Root exception had been thrown in AmqpTransportHandler.RoundTripTwinMessage. Because the dictionary type is ConcurrentDictionary, it looks that only received twin message handling code remove entry from the dictionary, thus it suggests there were IoT Hub bug or timing issue of AmqpTransportHandler initialization.

I also found that the stacktrace of the exception which had been thrown by DeviceClient is corrupted because of rethrowing statement in DeviceClient. So, the statement

throw t.Exception.InnerException;

should be

ExceptionDispatchInfo.Capture(t.Exception.InnerException).Throw();

to preserve its stacktrace (if the throw statement does not intentionally truncate original stacktrace).

I hope this helps you.

[zolvarga]

@dmytro-gokun @yfakariya

Thanks for the info guys, we are looking at it.

Best Regards,
Zoltan

[dmytro-gokun]

@zolvarga Okay, here's an update. I've recently updated Microsoft.Azure.Devices.Client.dll to 1.7.0
The exception is not gone, so the bug has not been fixed. But, now i see one more exception. Also, thrown from time to time from the same GetTwinAsync call:

Microsoft.Azure.Devices.Client.Exceptions.IotHubException: {"errorCode":409002,"trackingId":"5912ff625167484da77b4e968d327408-G:14-TimeStamp:03/19/2018 08:49:19","message":"Conflict","timestampUtc":"2018-03-19T08:49:19.5247117Z"} at Microsoft.Azure.Devices.Client.DeviceClient.<>c.<ApplyTimeoutTwin>b__76_2(Task``1 t) at System.Threading.Tasks.ContinuationResultTaskFromResultTask``2.InnerInvoke() at System.Threading.Tasks.Task.Execute() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Keatech.Thinkrace.Gateway.Handlers.PropertySender.<UpdateTwinAsync>d__11.MoveNext() in D:\users\Dmytro\work\Keatech\git\Keatech.Thinkrace.Gateway\Handlers\PropertySender.cs:line 98 --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Keatech.Thinkrace.Gateway.Handlers.PropertySender.<UpdateAsync>d__10.MoveNext() in D:\users\Dmytro\work\Keatech\git\Keatech.Thinkrace.Gateway\Handlers\PropertySender.cs:line 85

PropertySender.cs:line 98 is:

var twin = await _deviceClient.GetTwinAsync();

This new exception happens several times a day and is really-really annoying.

[dmytro-gokun]

@zolvarga This new exception from GetTwinAsync is very similar to the first exception I described here: https://github.com/Azure/azure-iot-sdk-csharp/issues/420 I think these two issues are related.

[dmytro-gokun]

@CIPop KeyNotFoundException does not look like a service-side issue, right? Or, do you want me to open a support ticket for this one as well?

[ms-schneider-electric]

UPDATE This seems to only be an issue when I am using AMQP. When I switched the transport to MQTT these errors when away.

I am also seeing this issue consistently when using with several DeviceClient instances in the same process making calls to UpdateReportedPropertiesAsync.

The more client instances I use the more errors I get from this.

        private async Task TwinReportedAsync(TwinCollection reported)
        {
            try
            {
                this.logger.LogDSPDebug("Sending twin update.", deviceId: this.deviceId);
                await this.client.UpdateReportedPropertiesAsync(reported).ConfigureAwait(false);
                this.logger.LogDSPDebug("Sent twin update.", deviceId: this.deviceId);
            }
            catch (Exception ex)
            {
                this.logger.LogDSPError(0, ex, "Error updating twin.", deviceId: this.deviceId);
            }
        }

System.Collections.Generic.KeyNotFoundException
  HResult=0x80131577
  Message=The given key was not present in the dictionary.
  Source=Microsoft.Azure.Devices.Client
  StackTrace:
   at Microsoft.Azure.Devices.Client.DeviceClient.<>c.<ApplyTimeout>b__74_2(Task t)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SE.DSP.IoT.Simulator.IotHubDevice.<TwinReportedAsync>d__20.MoveNext() in C:\Sandbox\SE\IoTSimulator\SE.DSP.IoT.Simulator\IotHubDevice.cs:line 197

[schungx]

Same situation here. Calls to DeviceClient.GetDeviceTwin will regularly time-out or come back with errors or come back with no data inside.

This always seem to happen when:

1. Multiple DeviceClient instances are being used (>1). For example, it starts happening when two DeviceClient instances are being called one after the other. When using only one instance, the call mostly comes back ok.

2. Calls are made to different DeviceClient instances in close proximity

It smells suspiciously like DeviceClient is not re-entrant and multiple instances conflict with each other.

[schungx]

More information. This is especially the case when the device in question is being updated frequently from somewhere else.

So an easy way to reproduce this is:

1. Have a device and update reported property regularly. I've tried from once every few seconds to once every few minutes.

2. Try to read twin from that device. It will most likely take a long time-out or fail miserably. It fails or times out when the updated is done once every few seconds. It takes a LONG time (e.g. 30-40 seconds) to come back when the update is done once every few minutes.

Is there a rate throttle in play here?

[schungx]

Update: I realize that it could be failing due to rate limits. I'm testing using the Free tier, which has rate limits on the number of requests per second. A number of processes updating/reading at the same time could be the reason why the requests were failing.

Nevertheless, the error messages did not help at all in diagnosis.

[CIPop]

@dmytro-gokun You are getting a Conflict error in the one above. I don't think that's the same issue here.

@schungx We believe this was fixed in the latest release: 1.18.0. Please try again and let us know if you still see it. Closed by #586.

[az-iot-builder-01]

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