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.
2013-09-18 19:14
Tugberk Ugurlu


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:

image

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:

image

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.



Comments

Reid
by Reid on Tuesday, Oct 29 2013 20:08:47 +02:00

Thank you for the tutorial (and your git repository of examples)

I am perplexed by this behavior that I am encountering after configuring my .csproj to use OwinHost.exe to host the StartUp: whenever I F5 another project in my assembly (after setting it as the Start up project), the OwinHost.exe tied to this Logger project's hosting inexplicably launches in the background and then fails after failing to locate an automatic Startup. 

Have you encountered this? It seems to be a bug with Visual Studio 2013 that necessitates I keep my LoggingExample .csproj unloaded from the .sln when F5ing other applications in the .sln.

Reid
by Reid on Tuesday, Oct 29 2013 20:26:19 +02:00

Found the culprit - there is a project property added for OWINHost-implementing .csprojs : "Always Start When Debugging" which defaults to true. The behavior makes it so that ANY project in the .sln that is debugged causes the OWINHost to launch which is probably unintended.

Luke
by Luke on Friday, Dec 06 2013 12:38:09 +02:00

Great tutorial! Unfortunately, I am having a problem being on Windows 7 where the logging mechanism above doesn't seem to work as it should do.

For reference to my problem, please see my stackoverflow question as I think ti will be easier to read:

http://stackoverflow.com/questions/20423016/how-to-enable-owin-logging-on-windows-7

 

Thanks again,

 

Luke

Yannic Staudt
by Yannic Staudt on Monday, Dec 29 2014 10:29:27 +00:00
Hello, first of all thank you very much for this introduction! It gave the me right clues to build my NLog adapter: http://k16c.eu/2014/12/27/using-nlog-owin-logger/
Sam
by Sam on Friday, Feb 06 2015 20:45:30 +00:00
Nice article! Is there a way that I can inject Enterprise Library LogWriter in OWIN? Thanks! Sam
zapya
by zapya on Tuesday, Oct 25 2016 11:52:18 +00:00
Download Zapya for PC to share files and folders easily from PC to other devices

Tags