Logging in the OWIN World with Microsoft.Owin: Introduction
Microsoft implementation of OWIN (Microsoft.Owin or Katana for now) has a great logging infrastructure and this post will walk you through the basics of this component.
18 September 2013
6 minutes read
Related Posts
Microsoft implementation of OWIN (called Microsoft.Owin or Katana for now) has a great infrastructure for logging under Microsoft.Owin.Logging namespace inside the Microsoft.Owin assembly. Same as all other Microsoft.Owin components, the logging infrastructure is built on top of interfaces and there are two of them: ILoggerFactory and ILogger. The default implementation is using .NET Framework tracing components heavily such as System.Diagnostics.TraceSource and System.Diagnostics.TraceSwitch. You can learn about these components and how to instrument your applications with them through the .NET Development Guide's Tracing section on MSDN.
The responsibility of the logger factory is to construct a new logger when needed. You can see how ILoggerFactory interface looks like below:
namespace Microsoft.Owin.Logging { /// <summary> /// Used to create logger instances of the given name. /// </summary> public interface ILoggerFactory { /// <summary> /// Creates a new ILogger instance of the given name. /// </summary> /// <param name="name"></param> /// <returns></returns> ILogger Create(string name); } }
As you can see, the Create method returns an ILogger implementation. The ILogger implementation is solely responsible for writing the logs through its one and only method: WriteCore.
namespace Microsoft.Owin.Logging { /// <summary> /// A generic interface for logging. /// </summary> public interface ILogger { /// <summary> /// Aggregates most logging patterns to a single method. This must be compatible with the Func representation in the OWIN environment. /// /// To check IsEnabled call WriteCore with only TraceEventType and check the return value, no event will be written. /// </summary> /// <param name="eventType"></param> /// <param name="eventId"></param> /// <param name="state"></param> /// <param name="exception"></param> /// <param name="formatter"></param> /// <returns></returns> bool WriteCore(TraceEventType eventType, int eventId, object state, Exception exception, Func<object, Exception, string> formatter); } }
For these interfaces, there are two implementations provided by the Microsoft.Owin assembly for logging: DiagnosticsLoggerFactory (publicly exposed) and DiagnosticsLogger (internally exposed). However, these are the types provided by the Microsoft's OWIN implementation and don't belong to core .NET framework. As it's discouraged to put non-framework types inside the IAppBuilder properties dictionary and request's environment, a Func is put inside the IAppBuilder properties dictionary with a key named "server.LoggerFactory". Here is the signature of that Func.
using TraceFactoryDelegate = Func < string, Func < TraceEventType, int, object, Exception, Func < object, Exception, string >, bool > >;
Through this delegate, you are expected to create a Func object based on the logger name and this Func will be used to write logs. The currently provided extension methods to work with the Katana’s logging infrastructure hides these delegates from you. Here are a few extension methods under Microsoft.Owin.Logging namespace for the IAppBuilder interface:
public static void SetLoggerFactory( this IAppBuilder app, ILoggerFactory loggerFactory); public static ILoggerFactory GetLoggerFactory( this IAppBuilder app); public static ILogger CreateLogger( this IAppBuilder app, string name);
All these extension methods work on the TraceFactoryDelegate Func instance shown above but it’s all hidden from us as mentioned.
So, how we can take advantage of this provided components? It’s quite easy actually. You can create separate loggers for each of your components using one of the CreateLogger extension method overloads for the IAppBuilder interface and use that logger to write log messages. The following is just a little sample to give you a hint:
public class Startup { public void Configuration(IAppBuilder app) { Log1(app); app.Use<MyCustomMiddleware>(app); } private void Log1(IAppBuilder app) { ILogger logger = app.CreateLogger<Startup>(); logger.WriteError("App is starting up"); logger.WriteCritical("App is starting up"); logger.WriteWarning("App is starting up"); logger.WriteVerbose("App is starting up"); logger.WriteInformation("App is starting up"); int foo = 1; int bar = 0; try { int fb = foo / bar; } catch (Exception ex) { logger.WriteError("Error on calculation", ex); } } } public class MyCustomMiddleware : OwinMiddleware { private readonly ILogger _logger; public MyCustomMiddleware( OwinMiddleware next, IAppBuilder app) : base(next) { _logger = app.CreateLogger<MyCustomMiddleware>(); } public override Task Invoke(IOwinContext context) { _logger.WriteVerbose( string.Format("{0} {1}: {2}", context.Request.Scheme, context.Request.Method, context.Request.Path)); context.Response.Headers.Add( "Content-Type", new[] { "text/plain" }); return context.Response.WriteAsync( "Logging sample is runnig!"); } }
There are a few things I would like to touch on here:
- I used generic CreateLogger method to create loggers. This will create loggers based on the name of the type I’m passing in. In view of the default logger implementation provided by the Katana, this means that we will create TraceSource instances named as the full type name.
- You can see that I receive an IAppBuilder implementation instance through the constructor of my middleware and I used that instance to create a logger specific to my middleware. I can hold onto that logger throughout the AppDomain lifetime as all members of my logger are thread safe.
- Instead of using the WriteCore method to write logs, I used several extension methods such as WriteVerbose to write specific logs.
This is not enough by default as we didn’t configure what kind of tracing data we are interested in and how we would like to output them. We need to configure Trace Switches and Trace Listeners properly to instrument our application. Microsoft.Owin is root switch and if we enable it, we will see all messages we write through our loggers. The following configuration will enable the Microsoft.Owin switch:
<configuration> <system.diagnostics> <switches> <add name="Microsoft.Owin" value="Verbose" /> </switches> </system.diagnostics> </configuration>
When we run our application on Debug mode, we can see that the Output window will show our log data:
We can take it further and configure different listeners for different switches. The following configuration will enable TextWriterTraceListener for LoggingSample.MyCustomMiddleware SourceSwitch:
<configuration> <system.diagnostics> <switches> <add name="Microsoft.Owin" value="Verbose" /> </switches> <sharedListeners> <add name="console" type="System.Diagnostics.ConsoleTraceListener" /> </sharedListeners> <trace autoflush="true" /> <sources> <source name="Microsoft.Owin"> <listeners> <add name="console" /> </listeners> </source> <source name="LoggingSample.MyCustomMiddleware"> <listeners> <add name="file" type="System.Diagnostics.TextWriterTraceListener" initializeData="traces-MyCustomMiddleware.log" /> </listeners> </source> </sources> </system.diagnostics> </configuration>
Now we can see that our middleware’s logs will only be written into traces-MyCustomMiddleware.log file:
I think this post should give you a pretty good understanding of how Katana’s logging infrastructure has been set up and works under the hood. I plain on writing a few more posts on this logging infrastructure. So, stay tuned. Also, as I get used to the concepts of OWIN, I started to think that this logging infrastructure is more fitting as an OWIN extension (just like the SendFile extension) rather than being tied to Katana.
The sample I used here also available on GitHub inside my OwinSamples repository.
Hey, I'm Tugberk 👋
Coder 👨🏻💻, Speaker 🗣, Author 📚, ex-Microsoft MVP 🕸, Blogger 💻
I live in London, UK 🏡
