Web API Tracing Stack Overflow

Topics: ASP.NET Web API
Mar 22, 2013 at 9:57 PM
Edited Mar 22, 2013 at 11:14 PM
I've been running into a stack overflow issue with Web API tracing. Tried a few debugging options, but I can't seem to find any way to dig into the problem any deeper.

Once I enable tracing on my Web API Odata project, the first request stack overflows with the following trace (abbreviated here):
System.Web.Http.Tracing.ITraceWriterExtensions.TraceBeginEndAsync<System.Net.Http.HttpResponseMessage>(System.Web.Http.Tracing.ITraceWriter traceWriter, System.Net.Http.HttpRequestMessage request, string category, System.Web.Http.Tracing.TraceLevel level, string operatorName, string operationName, System.Action<System.Web.Http.Tracing.TraceRecord> beginTrace, System.Func<System.Threading.Tasks.Task<System.Net.Http.HttpResponseMessage>> execute, System.Action<System.Web.Http.Tracing.TraceRecord,System.Net.Http.HttpResponseMessage> endTrace, System.Action<System.Web.Http.Tracing.TraceRecord> errorTrace)    
System.Web.Http.Tracing.Tracers.RequestMessageHandlerTracer.SendAsync(System.Net.Http.HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
System.Net.Http.DelegatingHandler.SendAsync(System.Net.Http.HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
System.Web.Http.HttpServer.SendAsync(System.Net.Http.HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
System.Net.Http.HttpMessageInvoker.SendAsync(System.Net.Http.HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
System.Web.Http.WebHost.HttpControllerHandler.BeginProcessRequest(System.Web.HttpContextBase httpContextBase, System.AsyncCallback callback, object state)
System.Web.Http.WebHost.HttpControllerHandler.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext httpContext, System.AsyncCallback callback, object state)
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
And you get the idea - I keep seeing a call to System.Net.Http.DelegatingHandler.SendAsync that triggers tracing and another call back to SendAsync.

I've noticed that if I comment out a call to config.Services.GetHttpControllerSelector().GetControllerMapping() that's made after config.EnableSystemDiagnosticsTracing() the issue goes away.
Mar 23, 2013 at 12:12 AM
After a bit more "debugging" it seems that, amazingly, the number of controllers in the project has an effect. If I create about 4-5 blank controllers, I can cause the overflow to happen. It's a bit inconsistent how many I need, perhaps a race condition is involved here somewhere?

I disabled just about all code in my project, and my blank EntitySetControllers are pointing at Object as the entity type. All I can figure is there must be a serious bug in Web API Tracing somewhere.
Mar 25, 2013 at 3:17 PM
It will help diagnose this issue if you can provide an app that demonstrates this, because I haven't heard of it before. Did you add any custom MessageHandlers? The RequestMessageHandlerTracer is the first MessageHandler executed when tracing is enabled and a request is received. It invokes TraceBeginEndAsync that does 3 things -- (1) trace a record saying "request received", (2) invokes the RequestMessageHandlerTracer's base.SendAsync (which calls the next MessageHandler in the pipeline), and then (3) asynchronously traces "request complete". For the stack to overflow, one of the MessageHandlers must be going recursive, almost certainly at (2). The fact it calls TraceBeginEndAsync() suggests at least the "begin" part of the request is traced. Can you verify that? What does that trace contain? I would expect you to see a begin trace record for each new re-entrant call leading to stack overflow.

Note each MessageHandler's SendAsync synchronously calls the next handler in the pipeline and asynchronously deals with the returned Task<HttpResponseMessage>. For this to stack overflow, we're likely looking at just the synchronous part.

I recommend debugging this by inserting your own MessageHandler (HttpConfiguration.MessageHandlers.Add()) and then setting a breakpoint on your message handler's SendAsync. RequestMessageHandlerTracer will execute synchronously before and asynchronously after your handler's SendAsync. You should see it break each recursive call and possibly understand from the stack trace why it has gone recursive before stack overflow. An alternate way to debug is by inserting your own ITraceWriter implementation and setting a breakpoint on its Trace() method.

Also, when do you call GetControllerMapping()? Before the first request? After?

I suspect either the pipeline is corrupt or one of the MessageHandlers is going recursive. It is possible your code calls WebAPI in a legal way but at an unexpected time, which is why a repro app would help narrow this.
Mar 25, 2013 at 5:24 PM
GetControllerMapping is called before the first request. I'm working on trying to narrow down a test project, but it's ugly - small, meaningless changes such as renaming namespaces(!) seem to have an effect even when I delete the bin & obj directories before each test. Maybe I need more caffeine ;-)

Are the source code or PDBs for System.Web.Http.Tracing 4.0.0.0 available anywhere? Can't seem to find them on the Microsoft Symbols Server.

I don't have any of my own MessageHandlers installed. I tossed in a custom ITraceWriter and I see the following:
  • System.Net.Http.DelegatingHandler.SendAsync calls System.Http.Tracing.Tracers.MessageHandlerTracer.SendAsync
  • Inside MessageHandlerTracer.SendAsync, I can see the problem. The InnerHandler of the "this" MessageHandlerTracer is another MessageHandlerTracer with a different object id.
  • The InnerHandler recursively points to another MessageHandlerTracer - I see four separate MessageHandlerTracer instances constructed in a loop. MessageHandlerTracer#1->MessageHandlerTracer#2->MessageHandlerTracer#3->MessageHandlerTracer#4->MessageHandlerTracer#1, etc.
None of my types appear in the recursive call stack - they're all System.* assemblies.

I suspected that the issue might be due to the time GetControllerMapping takes to execute, so I tossed in a Thread.Sleep there - didn't cause the problem. I'll keep working on the repro project, but I'm fairly certain nothing in my code is mucking with the MessageHandler chain or tracing.
Mar 25, 2013 at 6:31 PM
There is only one place that MessageHandlerTracer's are inserted into the pipeline -- the ITraceManager implementation. The next step to find the problem is to write your own ITraceManager implementation that delegates to the one already installed in the config.Services. You should see ITraceManager.Initialize() called exactly once before the first request is serviced. If you are using per-controller-configuration, you will also see calls happening when you first call GetControllerMapping().

The ITraceManager.Initialize inserts a new MessageHandlerTracer in front of every MessageHandler, effectively doubling the number of handlers in the pipeline. It also adds the RequestMessageHandlerTracer to make an outermost tracer for the request.

If you break at your ITraceManager.Initialize(), step over the call into the existing one and see the config.MessageHandler collection become mangled as you show above, you have found the problem. Note that the Initialize call is supposed to be idempotent and self-protect against redundant MessageHandlerTracer wrappers. Something is defeating that idempotency check. It is perfectly legal to have multiple MessageHandlers of course, which would also mean multiple MessageHandlerTracers. But it is illegal for a loop to form.

Sorry to make you debug this. I don't believe symbols for Tracing were published. I don't see them at http://www.symbolsource.org/Public/Metadata/NuGet which is where the other WebAPI symbols live.
Mar 25, 2013 at 6:56 PM
Edited Mar 25, 2013 at 7:01 PM
I just literally showed another developer here how changing a controller class name will cause the bug to appear/disappear. I zipped the simplest version of the project I can, and the other dev was able to reproduce it on his machine.

Sent you a private message with a link to the sample project on SkyDrive.

Will get back to you on the trace manager test.
Mar 25, 2013 at 7:33 PM
Edited Mar 25, 2013 at 7:34 PM
Here's what I'm seeing during calls to ITraceManager.Initialize:

Initialize #1:
After this initialize call, I see one MessageHandler in the config - RequestMessageHandlerTracer. Its InnerHandler is null.
  1. The call to DefaultHttpControllerSelector.GetControllerMaping() calls Get on a Lazy<ConcurrentDictionary<string,HttpControllerDispatcher>>
  2. Lazy<T>.Get calls LazyInitValue then CreateValue
  3. Call to DefaultHttpControllerSelector.InitializeControllerInfoCache
  4. Call to HttpControllerDescriptor constructor
  5. Call to HttpControllerDescriptor.Initialize
  6. Call to HttpControllerDescriptor.InvoleAttributesOnControllerType (which calls an overload of itself)
  7. Call to HttpConfiguration.ApplyControllerSettings
  8. Call to HttpConfiguration.DefaultInitializer
  9. Call to ITraceManager.Initialize
Initialize #2:
After this initialize call, I see three MessageHandlers - two RequestMessageHandlerTracer and one MessageHandlerTracer. No innerHandler loop yet.
  • Stack trace looks the same as Initialize #1 - called from within the GetControllerMapping->Lazy->HttpControllerDescriptor.ctor chain.
Initialize #3:
Now I see 7 message handlers, all tracing. No innerhandler loops. Same stack trace.

Initialize #4:
15 message handlers, all tracing.

And continuing with each call to ITraceManager.Initialize, counting message handlers:
31, 64, 255, 511, 1023, 2047, 4095, 8191.

The last call to ITraceManager.Initialize was the "8191" call, and is within HttpServer.SendAsync, not Application_Start.

None of the message handlers seem to have an InnerHandler assigned. Looks like it's not truly overflowing on a recursive loop, just a massive number of handlers. The behavior you mentioned about how the number of trace managers "doubles" makes sense - that's precisely what I'm seeing.

My hypothesis: Web API Tracing installs its "wrapping" MessageHandlers each time HttpConfiguration.ApplyControllerSettings is called. Each time a HttpControllerDescriptor is constructed, ApplyControllerSettings is called (a bug or design oversight?). Calling "GetControllerMapping" causes a large number of HttpControllerDescriptors to be constructed, and the number of descriptors it creates is dependent on the number of controllers in the assembly. Renaming a small number of controllers got rid of the StackOverflowException for me since less data was placed in the stack.

The issue probably didn't show up during testing because requests to "$metadata" don't cause the behavior to occur. Perhaps the call to GetControllerMapping() has different behavior during Application_Start.
Mar 25, 2013 at 7:56 PM
The repro demonstrates this is a legitimate product bug.
I opened issue http://aspnetwebstack.codeplex.com/workitem/938 for it.
I'm investigating a workaround now.

The issue is that GetControllerMapping will corrupt the MessageHandler pipeline if called before the pipeline has been wired up by the first request.
Mar 25, 2013 at 8:20 PM
I don't see an obvious workaround. The conditions necessary to finish pipeline initialization (and therefore tell the tracing layer it may not be modified) cannot be invoked by user code. I tried writing a wrapping initializer over HttpConfiguration.Initializer() to do user initialization after the default, but this still gives stack overflow. GetControllerMapping must be called after the first request has been received so the pipeline is setup.
Mar 26, 2013 at 1:57 PM
I have verified one workaround. User code can insert a MessageHandler during configuration, and this MessageHandler can do a one-time initialization (under a lock) before its SendAsync() calls base.SendAsync(). Experiments show HttpServer.Initialize() will be called before this custom MessageHandler is called, and therefore the handler will be working with a fully initialized HttpConfiguration. Moreover, the remainder of the WebAPI MessageHandler pipeline has not yet been called, so it is not too late to set up a DI container or perform other initialization. Note that the HttpConfiguration should not be modified from this MessageHandler, only read.