ASP.NET Web API Tracing and IDependencyScope Dispose Issue
If you enabled tracing on your ASP.NET Web API application, you may see a dispose issue for IDependencyScope. Here is why and how you can workaround it.
12 January 2013
5 minutes read
Related Posts
ASP.NET Web API has a very cool built-in tracing mechanism. The coolest part about this feature is that none of the tracing code is being run if you don’t enable it. The mechanism makes use of well-known Facade Pattern and if you enable tracing by providing your custom ITraceWriter implementation and don’t replace the default ITraceManager implementation, several ASP.NET Web API components (Message Handlers, Controllers, Filters, Formatters, etc.) will be wrapped up inside their tracer implementations (these are internal classes inside System.Web.Http assembly). You can learn more about tracing from Tracing in ASP.NET Web API article.
ASP.NET Web API also has this concept of carrying disposable objects inside the request properties bag and two objects are added to this disposable list by the framework as shown below (in the same order):
- The IDependencyScope implementation for the request.
- The selected IHttpController implementation for the request.
The DisposeRequestResources extension method for the HttpRequestMessage object is invoked by the hosting layer at the end of each request to dispose the registered disposable objects. The invoker is the internal ConvertResponse method of HttpControllerHandler in case of ASP.NET host. The implementation of the DisposeRequestResources extension method is exactly as shown below:
public static void DisposeRequestResources(this HttpRequestMessage request) { if (request == null) { throw Error.ArgumentNull("request"); } List<IDisposable> resourcesToDispose; if (request.Properties.TryGetValue(HttpPropertyKeys.DisposableRequestResourcesKey, out resourcesToDispose)) { foreach (IDisposable resource in resourcesToDispose) { try { resource.Dispose(); } catch { // ignore exceptions } } resourcesToDispose.Clear(); } }
It iterates through the list and disposes the registered objects one by one. So far so good. However, there is one slightly problem here depending on your ITraceWriter implementation. I’m not sure if it’s fair to call this a bug, but to me, it really is a bug. Let me explain what it is.
As we know, the IDependencyScope implementation and the selected IHttpController implementation for the request are added to the disposables list in order to be disposed at the end of the request. As we also know, if we enable tracing in ASP.NET Web API, several ASP.NET Web API components wrapped inside their tracer implementations. In case of controllers, this is HttpControllerTracer. Since the IHttpController is also disposable, the HttpControllerTracer overrides the Dispose method to write a begin/end trace record for the dispose action. However, the disposable objects are disposed in order and when the controller’s dispose method is called, the dependency scope is already too far gone and if your custom ITraceWriter implementation tries to use the dependency scope, which is bound to that request, you will get an exception there. This doesn’t effect your application that much as this exception is swollen by the underlying infrastructure but this is not good. I wrote a little application to demonstrate this (actually, I went a little far and used a few more things for this *little* application 
) and show how to workaround it for now. The code for this project is available on GitHub.
I created a custom tracer and registered through the global HttpConfiguration instance. This tracer tries to reach the ILoggerService implementation through the dependency scope. The code for my ITraceWriter implementation is as shown below:
public class WebApiTracer : ITraceWriter { public void Trace( HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction) { if (level != TraceLevel.Off) { TraceRecord record = new TraceRecord(request, category, level); traceAction(record); Log(record); } } private void Log(TraceRecord traceRecord) { IDependencyScope dependencyScope = traceRecord.Request.GetDependencyScope(); ILoggerService loggerService = dependencyScope.GetService(typeof(ILoggerService)) as ILoggerService; // Log the trace data here using loggerService // Lines omitted for brevity } }
When we run this application in debug mode and send a request against a valid resource which will eventually go inside the controller pipeline (for this application /api/cars), we will see an exception as below:
If we are curios enough and decide to dig a little deeper, we will actually see what is causing this exception.
{"Instances cannot be resolved and nested lifetimes cannot be created from this LifetimeScope as it has already been disposed."}
at Autofac.Core.Lifetime.LifetimeScope.CheckNotDisposed()
at Autofac.Core.Lifetime.LifetimeScope.ResolveComponent(IComponentRegistration registration, IEnumerable`1 parameters)
at Autofac.ResolutionExtensions.TryResolveService(IComponentContext context, Service service, IEnumerable`1 parameters, Object& instance)
at Autofac.ResolutionExtensions.ResolveOptionalService(IComponentContext context, Service service, IEnumerable`1 parameters)
at Autofac.ResolutionExtensions.ResolveOptional(IComponentContext context, Type serviceType, IEnumerable`1 parameters)
at Autofac.ResolutionExtensions.ResolveOptional(IComponentContext context, Type serviceType)
at Autofac.Integration.WebApi.AutofacWebApiDependencyScope.GetService(Type serviceType)
at DependencyScopeTracingDisposeBug.Tracing.WebApiTracer.Log(TraceRecord traceRecord) in e:\Apps\DependencyScopeTracingDisposeBug\Tracing\WebApiTracer.cs:line 25
at DependencyScopeTracingDisposeBug.Tracing.WebApiTracer.Trace(HttpRequestMessage request, String category, TraceLevel level, Action`1 traceAction) in e:\Apps\DependencyScopeTracingDisposeBug\Tracing\WebApiTracer.cs:line 18
at System.Web.Http.Tracing.ITraceWriterExtensions.TraceBeginEnd(ITraceWriter traceWriter, HttpRequestMessage request, String category, TraceLevel level, String operatorName, String operationName, Action`1 beginTrace, Action execute, Action`1 endTrace, Action`1 errorTrace)
at System.Web.Http.Tracing.Tracers.HttpControllerTracer.System.IDisposable.Dispose()
at System.Net.Http.HttpRequestMessageExtensions.DisposeRequestResources(HttpRequestMessage request)
It wasn’t hard to diagnose the problem and the question was how to workaround it for now as the issue is caused by a code which is deep inside the bowel of the hosting layer. There are several workarounds for this problem which I can come up with quickly such as replacing the HttpControllerTracer but the one I applied was very dirty: adding a message handler as the first message handler (so that it runs last (just in case)) and reordering the disposables on the way out. Here is the message handler which performs this operation:
public class DisposableRequestResourcesReorderHandler : DelegatingHandler { protected override Task<HttpResponseMessage> SendAsync( HttpRequestMessage request, CancellationToken cancellationToken) { return base.SendAsync(request, cancellationToken).Finally(() => { List<IDisposable> disposableResources = request.Properties[HttpPropertyKeys.DisposableRequestResourcesKey] as List<IDisposable>; if (disposableResources != null && disposableResources.Count > 1) { // 1-) Get the first one (which I know is AutofacWebApiDependencyScope). // 2-) Remove it from the list. // 3-) Push it at the end of the list. IDisposable dependencyScope = disposableResources[0]; disposableResources.RemoveAt(0); disposableResources.Add(dependencyScope); } }, runSynchronously: true); } }
Notice that I used an extension method for Task object called Finally. This is a method which you can get by installing the TaskHelpers NuGet package. This allows you to run the continuation no matter what the status of the completed Task. Finally method will also propagate the proper Task back to the caller, which is kind of nice and clean in our case here as we want to run this code no matter what the status of the Task is.
When you run the application after registering this message handler, you will see the controller’s dispose trace record being logged successfully.
If you believe this is a bug and should be fixed, please vote for this issue: http://aspnetwebstack.codeplex.com/workitem/768.
Hey, I'm Tugberk 👋
Coder 👨🏻💻, Speaker 🗣, Author 📚, ex-Microsoft MVP 🕸, Blogger 💻
I live in London, UK 🏡
