Search code examples
c#.netowin

.NET WebApp.Start() triggers run-away Tracing; Library Bug or incorrect usage?

I've found something that feels like a (minor) bug in .NET library code, and I wanted to check whether I had mis-configured the usage in some manner?

I have an C# Web API, using OWIN and running on .NET 4.6.1 (sigh)

During IntegrationTests we spin up in-memory instances of the API and poke it. For annoying reasons (which I'm looking into fixing independently) we spin up a new instance of the API per-test. I've recently discovered that if I have an nlog trace record Tracing to the "VSConsole" target the writing a single line of Trace will actually write it N times, where N is the number of tests that have run so far. Digging into it I found that the cause lay in Microsoft.Owin.Hosting.WebApp.Start(): A few levels down that method calls Microsoft.Owin.Hosting.Engine.HostingEngine.Start(), which calls EnableTracing(), which looks like this:

private void EnableTracing(StartContext context)
{
  TextWriterTraceListener writerTraceListener = new TextWriterTraceListener(context.TraceOutput, "HostingTraceListener");
  Trace.Listeners.Add((TraceListener) writerTraceListener);
  TraceSource traceSource = new TraceSource("HostingTraceSource", SourceLevels.All);
  traceSource.Listeners.Add((TraceListener) writerTraceListener);
  context.Builder.Properties["host.TraceOutput"] = (object) context.TraceOutput;
  context.Builder.Properties["host.TraceSource"] = (object) traceSource;
  context.Builder.SetLoggerFactory(this._loggerFactory);
}

Notably, this is adding a Listener without checking for any existing listeners. So if you repeatedly start and close new WebApps then you add more and more listeners to the Trace.Listeners collection. Which then means when you Trace to it, it writes out to the VSConsole repeatedly.

I've checked and there's nothing in the IDisposable output of WebApp.Start() that looks like it attempts to remove the listener either.

This ... seems like a bug :D

Direct Questions

  • Am I mis-using/mis-configuring it in some way?
  • Is it a bug in the .NET/OWIN code?
    • If so, is it still present in latest .NET?
    • If so, where should I report it?
  • Is there a sensible way to fix the issue in my tests? Some way to cleanup the Listeners between tests?
Solution

  • Calling Trace.Listeners.Clear(); before each WebApp start fixes the symptoms of the problem; ensures that there's only one Listener active at a time.