ASP.NET 5 Logging using Trace Listeners and How-to Filter Log Entries

Source code available at GitHub

Pluggable logging framework by ASP.NET 5...

ASP.NET 5 is the new open-source and cross-platform framework for building modern web applications using .NET. The new framework has in-built support for logging and it allows you to integrate with other logging frameworks too. You may need to write some code as a bridge between ASP.NET logging framework and your preferred logging provider by implementing interfaces provided by ASP.NET 5 such as ILoggingProvider and ILogger.

Can we plug trace listeners...?

In this post, I am going to cover how to use existing tracing framework in ASP.NET 5 projects. Tracing has been available in .NET since its inception. People have made investments into using trace listeners which write trace messages to a variety of destinations such as local file, database table, etc. They should be able to reuse their investment in ASP.NET 5 project as well. Let’s see how.

No more web.config...

Using tracing in in ASP.NET 4.x was fairly straight forward. You would define trace source and add trace listeners using web.config file. Something very simple as follows:

<system.diagnostics>
  <trace autoflush="true"></trace>
  <sources>
    <source name="MyServiceTraceSource" switchvalue="All">
      <listeners>
        <add name="MyServiceListener" type="System.Diagnostics.TextWriterTraceListener" initializedata="MyServiceLog.txt"></add>
      </listeners>
    </source>
  </sources>
</system.diagnostics>

And then in your code, you would write messages to trace source which would be received by the trace listener configured for trace source. That has changed with ASP.NET 5, as it does not use web.config file, we’ve lost that configuration-ability that we are so used to. Though, there’s nothing stopping us from defining trace listener configuration using new JSON config file and then using the same in code to create trace listeners that would listen for specific trace sources. For now, in this article, I am going to use trace listeners directly in code. 

Add tracing provider...

ASP.NET 5 has its own logging framework so we would need to plug trace listener provider to ASP.NET 5 logging framework. To use trace listeners in ASP.NET 5, you would need to add a NuGet package to your project called, Microsoft.Extensions.Logging.TraceSource. It has been developed by asp.net team as part of aspnet/Logging project. It lets you use TraceSource and TraceListener in your ASP.NET 5 project by using TraceSourceLogger class. 

You need to add Microsoft.Extensions.Logging.TraceSource package to your project as a dependency in project.json file as shown below:

"dependencies": {
    "Microsoft.AspNet.IISPlatformHandler": "1.0.0-rc1-final",
    "Microsoft.AspNet.Mvc": "6.0.0-rc1-final",
    "Microsoft.AspNet.Server.Kestrel": "1.0.0-rc1-final",
    "Microsoft.AspNet.StaticFiles": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.FileProviderExtensions": "1.0.0-rc1-final",
    "Microsoft.Extensions.Configuration.Json": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Console": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.Debug": "1.0.0-rc1-final",
    "Microsoft.Extensions.Logging.TraceSource": "1.0.0-rc1-final"
},

Add Trace Listener...

Next, you need to add a trace source listener to logger factory:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        new TextWriterTraceListener("AspNet5LoggingService.txt")
    );
    ...
}

Note: TextWriterTraceListener is not available in .Net Core but .Net Framework only so once you use it in your code, you may get compile error for the same. If you do, you would need to remove dnxcore50 target framework from your project by modifying project.json file i.e. remove highlighted line below:

"frameworks": {
  "dnx451": { },
  "dnxcore50": { }
},

Get Logger...

Lastly, you need to get logger instance in your classes by injecting a dependency to your class for logger instance. There is couple of options available for adding a dependency to class constructor for logger instance:

1. One option is to use ILoggerFactory type as a dependency and then manually creating a logger by calling CreateLogger method on factory instance and passing in a category name.

2. Another option is to use Logger<T> as a dependency in your constructor by specifying generic type parameter.

When using ILoggerFactory, you need to manually create a logger whereas with Logger<T> you could directly start using it for logging. For most situations, using Logger<T> would suffice but when you don’t know the generic type parameter to be used or if you would like to create a logger with a certain category name, you could use ILoggerFactory. Let’s look at an example using both approaches:

[Route("api/[controller]")]
public class ValuesController : Controller
{
    private readonly ILogger<ValuesController> logger;
    public ValuesController(ILogger<ValuesController> logger)
    {
        this.logger = logger;
    }
    ...
}

OR

[Route("api/values2")]
public class ValuesController2 : Controller
{
    private readonly ILogger logger;
    public ValuesController2(ILoggerFactory loggerFactory)
    {
        this.logger = loggerFactory.CreateLogger("AspNet5LoggingService");
    }
    ...
}

Use Logger...

Voila! You are done and now you can start using this logger instance to write log entries.

    [Route("api/[controller]")]
    public class ValuesController : Controller
    {
        private readonly ILogger<valuescontroller> logger;
        public ValuesController(ILogger<valuescontroller> logger)
        {
            this.logger = logger;
        }
        // GET: api/values
        [HttpGet]
        public IEnumerable<string> Get()
        {
            logger.LogInformation("Processing GET request for values.");
            return new string[] { "value1", "value2" };
        }
    }
</string></valuescontroller></valuescontroller>

When executed, it would write log entry in trace destination by trace listener, which in my case was the log file specified with TextWriterTraceListener.

Noisy log entries...

You would find that log file is created in wwwroot folder and it contains all log entries. But as you would have noticed, the log file also contains all log entries which are generated by ASP.NET 5 framework. You would see something like this:

Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 4 : Hosting starting
Microsoft.AspNet.Hosting.Internal.HostingEngine Verbose: 5 : Hosting started
Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 GET http://localhost:50998/api/values
Microsoft.AspNet.Hosting.Internal.HostingEngine Information: 1 : Request starting HTTP/1.1 DEBUG http://localhost:50998/ text/html
Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 1 : DEBUG requests are not supported
Microsoft.AspNet.StaticFiles.StaticFileMiddleware Verbose: 4 : The request path /api/values does not match a supported file type
...
...
AspNet5LoggingService Information: 0 : Processing GET request for values.

This behavior is by design. All logging providers will get all logging messages and it’s for individual provider to filter the "category" of messages they are interested in. Most likely, you wouldn’t want all those entries in log file along with log entries created by your service code and that brings us to next step.

How to filter for log entries...?

You can filter log entries by adding a filter to TraceListener, which is defined as a property on TraceListener base class. It’s of type TraceFilter:

public System.Diagnostics.TraceFilter Filter { get; set; }

If you lookup TraceFilter class definition, you would notice that it’s an abstract class. There are few default TraceFilter implementations available and you could use them or create your own filter very easily. All you would need to do is derive a class from TraceFilter and override ShouldTrace method. For this example, I am going to use existing SourceFilter class, which comes with .NET.

You could add a TraceFilter to your listener as follows:

var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
listener.Filter = new SourceFilter("AspNet5LoggingService");
loggerFactory.AddTraceSource(
    new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
    listener
);

Where are my filtered log entries...?

Depending upon your project and the number of log entries being generated, it may happen that you don’t see any new trace messages in your log file, especially after you filtered for trace messages generated by your service code. If you are using a TextWriterTraceListener, you may not see your log entries immediately in log file, though the log file would be created immediately (if it does not exist already). This is where I struggled and ended up spending quite some time debugging why I don't see log entries in my file, only to find out later about a feature with the specific listerner that I was using. This happens because TextWriterTraceListener writes data to the file stream and those trace messages are buffered. It does not flush the buffered data with each write. In previous versions of .NET, you would normally add following to your web.config file.

<trace autoflush="true" />

which would cause trace listeners to flush trace messages immediately. To achieve the same in ASP.NET 5, you can add following in code:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    loggerFactory.AddConsole(Configuration.GetSection("Logging"));
    loggerFactory.AddDebug();

    // This would prevent TextWriterTraceListener from buffering trace messages but cause
    // it to flush them as each trace message is sent to listener
    if (env.IsDevelopment())
    {
        Trace.AutoFlush = true;
    }

    var listener = new TextWriterTraceListener("AspNet5LoggingService.txt");
    listener.Filter = new SourceFilter("AspNet5LoggingService");
    loggerFactory.AddTraceSource(
        new SourceSwitch("AspNet5LoggingSwitch", "Verbose"),
        listener
    );
    ...
}

I am opting for AutoFlush behavior only in case of development environment because that's where we would need log entries to be reflected in file immediately whereas in production environment buffering log messages would give better performance. If you don’t set AutoFlush property, you would need to wait until buffered data in stream is written to file on disk.

Summary...

In this article we saw how to

1. Use trace listener in ASP.NET 5 project

2. Filter trace entries at the trace listener level

3. Use Trace.AutoFlush in code to prevent trace messages from being buffered in memory

NOTE: Please note that this article was written using ASP.NET 5 RC1 and by the time RTM comes out, which is expected in another couple of months, there may be some changes.

Happy Coding.

Vande Mataram!

(A salute to motherland)

CodeProject