KeyNotFoundException in Microsoft.Extensions.DiagnosticAdapter.Internal.ProxyTypeEmitter.GetProxyType

[davenewza]

The following KeyNotFoundException exception has been throwing during requests to our API. I cannot reproduce it and there seems to be no consistency as to when it happens.

An unhandled exception has occurred while executing the request
System.Collections.Generic.KeyNotFoundException: The given key was not present in the dictionary.
   at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
   at Microsoft.Extensions.DiagnosticAdapter.Internal.ProxyTypeEmitter.GetProxyType(ProxyTypeCache cache, Type targetType, Type sourceType)
   at Microsoft.Extensions.DiagnosticAdapter.Internal.ProxyFactory.CreateProxy[TProxy](Object obj)
   at Proxy_Method_From_<>f__AnonymousType0`3_To_Void OnBeforeAction(Microsoft.AspNetCore.Http.HttpContext, IRouteData)(Object , Object , IProxyFactory )
   at Microsoft.Extensions.DiagnosticAdapter.ProxyDiagnosticSourceMethodAdapter.<>c__DisplayClass1_0.<Adapt>b__0(Object listener, Object data)
   at Microsoft.Extensions.DiagnosticAdapter.DiagnosticSourceAdapter.Write(String diagnosticName, Object parameters)
   at Microsoft.Extensions.DiagnosticAdapter.DiagnosticSourceAdapter.System.IObserver<System.Collections.Generic.KeyValuePair<System.String,System.Object>>.OnNext(KeyValuePair`2 value)
   at System.Diagnostics.DiagnosticListener.Write(String name, Object value)
   at Microsoft.AspNetCore.Mvc.Internal.MvcCoreDiagnosticSourceExtensions.BeforeAction(DiagnosticSource diagnosticSource, ActionDescriptor actionDescriptor, HttpContext httpContext, RouteData routeData)
   at Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker.<InvokeAsync>d__20.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Builder.RouterMiddleware.<Invoke>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyApplication.Api.Middleware.Compression.CompressionMiddleware.<Invoke>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Cors.Infrastructure.CorsMiddleware.<Invoke>d__7.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at AspNetCoreRateLimit.ClientRateLimitMiddleware.<Invoke>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at AspNetCoreRateLimit.IpRateLimitMiddleware.<Invoke>d__6.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware`1.<Invoke>d__18.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware`1.<Invoke>d__18.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyApplication.Api.Middleware.NoCacheMiddleware.<Invoke>d__2.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at MyApplication.Mvc.Extensions.ApplicationBuilderExtensions.<>c__DisplayClass0_0.<<UseRequireHttps>b__0>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.<Invoke>d__7.MoveNext()

The project is targeting the full .NET 4.6 framework and the following NuGet packages:

Does anyone know what this could be caused by?

[davenewza]

Thrown from this method.

[Eilon]

@rynowak - any idea?

[rynowak]

The line that's throwing is probably here: https://github.com/aspnet/EventNotification/blob/master/src/Microsoft.Extensions.DiagnosticAdapter/Internal/ProxyTypeEmitter.cs#L75

Hypothesis:

1. We didn't find the proxy we need in the cache, so we decided to generate one. (Line 27)
2. We then verify that the types we want to generate are valid for proxying (Line 36)
3. As part of this process we add all of the types we need to context.Visited - this fails for a reason we need to figure out.
4. Then we assert that we've added the original type we were looking for to context.Visited (Line 43)
5. Then we end up at Line 75 and throw, since this is release we don't know that the assertion at Line 43 failed.

I think what's happened is in between steps 2-3 another operation completed and updated the cache with the same type that we're looking for. Then at Line 104 we check for this and early exit. *But we didn't add the result to context.Visited.

[Eilon]

Thanks, it certainly looked like some kind of race condition.

[jbagga]

@rynowak I added a test for the scenario where the Cache has the key but Visited does not and changed the source code accordingly.

However, I am not sure how to repro the original issue/exception.

[rynowak]

However, I am not sure how to repro the original issue/exception.

The original bug is a threading issue, it would be very hard to reproduce consistently. We don't generally try to write unit tests for race conditions, it requires a level of effort and sophistication that we don't usually put into unit tests.