Category Archives: Logging

Using Microsoft.Extensions.Logging

The Microsoft.Extensions.Logging namespace includes interfaces and implementations for a common logging interface. It’s a little like common-logging and whilst it’s not restricted to ASP.NET Core it’s got things entry points to work with ASP.NET Core.

What’s common logging all about?

In the past we’ve been hit with the problem of multiple logging frameworks/libraries which have slightly different interfaces. On top of this we might have other libraries which require those specific interfaces.

So for example, popular .NET logging frameworks such as log4net, NLog, Serilog along with the likes of the Microsoft Enterprise Block Logging might be getting used/expected in different parts of our application and libraries. Each ultimately offers similar functionality but we really don’t want multiple logging frameworks if we can help it.

The common-logging was introduced a fair few years back to allow us to write code with a standarised interface, but allow us to use whatever logging framework we wanted behind the scenes. Microsoft’s Microsoft.Extensions.Logging offers a similar abstraction.

Out of the box, the Microsoft.Extensions.Logging comes with some standard logging capabilities, Microsoft.Extensions.Logging.Console, Microsoft.Extensions.Logging.Debug, Microsoft.Extensions.Logging.EventLog, Microsoft.Extensions.Logging.TraceSource and Microsoft.Extensions.Logging.AzureAppServices. As the names suggest, these give us logging to the console, to debug, to the event log, to trace source and to Azure’s diagnostic logging.

Microsoft.Extensions.Logging offers is a relatively simple mechanism for adding further logging “providers” and third part logging frameworks such as NLog, log4net and SeriLog.

How to use Microsoft.Extensions.Logging

Let’s start by simply seeing how we can create a logger using this framework.

Add the Microsoft.Extensions.Logging and Microsoft.Extensions.Logging.Debug NuGet packages to your application.

The first gives us the interfaces and code for the LoggerFactory etc. whilst the second gives us the debug extensions for the logging factory.

Note: The following code has been deprecated and replaced with ILoggerBuilder extensions.

var factory = new LoggerFactory()
   .AddDebug(LogLevel.Debug);

Once the logger factory has been created we can create an ILogger using

ILogger logger = factory.CreateLogger<MyService>();

The MyService may be a type that you want to create logs for, alternatively you can pass the CreateLogger a category name.

Finally, using a standard interface we can log something using the following code

logger.Log(LogLevel.Debug, "Some message to log");

Using other logging frameworks

I’ll just look at a couple of other frameworks, NLog and Serilog.

For NLog add the NuGet package NLog.Extensions.Logging, for Serilog add Serilog.Extensions.Logging and in my case I’ve added Serilog.Sinks.RollingFile to create logs to a rolling file and Serilog.Sinks.Debug for debug output.

Using NLog

Create a file named nlog.config and set it’s properties within Visual Studio as Copy always. Here’s a sample

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
   xsi:schemaLocation="NLog NLog.xsd"
   xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
   autoReload="true"
   internalLogFile="c:\temp\mylog.log"
   internalLogLevel="Info" >


<targets>
   <target xsi:type="File" name="fileTarget" 
      fileName="c:\temp\mylog.log"      
      layout="${date}|${level:uppercase=true}|${message}
         ${exception}|${logger}|${all-event-properties}" />
   <target xsi:type="Console" name="consoleTarget"
      layout="${date}|${level:uppercase=true}|${message} 
         ${exception}|${logger}|${all-event-properties}" />
</targets>

<rules>
   <logger name="*" minlevel="Trace" writeTo="fileTarget,consoleTarget" />
</rules>
</nlog>

Now in code we can load this configuration file using

NLog.LogManager.LoadConfiguration("nlog.config");

and now the only difference from the previous example of using the LoggerFactory is change the creation of the factory to

var factory = new LoggerFactory()
   .AddNLog();

Everything else remains the same. Now you should be seeing a file named mylog.log in c:\temp along with debug output.

Using serilog

In Serilog’s case we’ll create the logger configuration in code, hence here’s the code to create both a file and debug log

Note: See Serilog documentation for creating the configuration via a config or settings file.

Log.Logger = new LoggerConfiguration()
   .MinimumLevel.Debug()
   .WriteTo.RollingFile("c:\\temp\\log-{Date}.txt")
   .WriteTo.Debug()
   .CreateLogger();

The will create a log file in c:\temp named log-{Date}.txt, where {Date} is replaced with today’s date. Obviously the include of WriteTo.Debug also gives us debug output.

We simply create the logger using familiar looking code

var factory = new LoggerFactory()
   .AddSerilog();

Everything else works the same but now we’ll see Serilog output.

Creating our own LoggerProvider

As you’ve seen in all examples, extension methods are used to AddDebug, AddNLog, AddSerilog. Basically each of these adds an ILoggerProvider to the factory. We can easily add our own provider by implementing the ILoggerProvider interface, here’s a simple example of a DebugLoggerProvider

public class DebugLoggerProvider : ILoggerProvider
{
   private readonly ConcurrentDictionary<string, ILogger> _loggers;

   public DebugLoggerProvider()
   {
      _loggers = new ConcurrentDictionary<string, ILogger>();
   }

   public void Dispose()
   {
   }

   public ILogger CreateLogger(string categoryName)
   {
      return _loggers.GetOrAdd(categoryName, new DebugLogger());
   }
}

The provider needs to keep track of any ILogger’s created based upon the category name. Next we’ll create a DebugLogger which implements the ILogger interface

public class DebugLogger : ILogger
{
   public void Log<TState>(
      LogLevel logLevel, EventId eventId, 
      TState state, Exception exception, 
      Func<TState, Exception, string> formatter)
   {
      if (formatter != null)
      {
         Debug.WriteLine(formatter(state, exception));
      }
   }

   public bool IsEnabled(LogLevel logLevel)
   {
      return true;
   }

   public IDisposable BeginScope<TState>(TState state)
   {
      return null;
   }
}

In this sample logger, we’re going to handle all LogLevel’s and are not supporting BeginScope. So all the work is done in the Log method and even that is pretty simple as we use the supplied formatter to create our message then output it to our log sink, in this case Debug. If no formatter is passed, we’ll currently not output anything, but obviously we could create our own formatter to be used instead.

Finally, sticking with the extension method pattern to add a provider, we’ll create the following

public static class DebugLoggerFactoryExtensions
{
   public static ILoggerFactory AddDebugLogger(
      this ILoggerFactory factory)
   {
      factory.AddProvider(new DebugLoggerProvider());
      return factory;
   }
}

That’s all there is to this very simple example, we create the factory in the standard way, i.e.

var factory = new LoggerFactory()
   .AddDebugLogger();

and everything else works without any changes.

Combining Serilog and Table Storage

As I’ve written posts on Serilog and Azure Storage recently, I thought I’d try to combine them both and use Azure table storage for the logging sink. Thankfully, I didn’t need to code anything myself, as this type of sink has already been written, see the AzureTableStorage sink.

If we take the basic code from Serilog revisited (now version 2.5) and Azure Table Storage and include the glue of AzureTableStorage. We get the following

  • Add NuGet Package Serilog.Sinks.AzureTableStorage
var storageAccount = CloudStorageAccount.Parse(
   CloudConfigurationManager.GetSetting(
   "StorageConnectionString"));

Log.Logger = new LoggerConfiguration()
   .WriteTo.AzureTableStorage(storageAccount, storageTableName: "MyApp")
   .CreateLogger();

Log.Logger.Information("Application Started");

for (var i = 0; i < 10; i++)
{
   Log.Logger.Information("Iteration {I}", i);
}

Log.Logger.Information("Exiting Application");

Without the storageTableName we’ll have the table LogEventEntity as the default table name. That’s all there is to it, now we’re sending our log entries into the cloud.

Serilog revisited (now version 2.5)

About a year ago, I wrote the post Structured logging with Serilog which covered the basics of using Serilog 2.0. I’ve just revisited this post and found Serilog 2.5 has changed things a little.

I’m not going to go over what Serilog does etc. but instead just list the same code from my original post, but working with the latest NuGet packages.

So install the following packages into your application using NuGet

  • Serilog
  • Serilog.Sinks.RollingFile
  • Serilog.Sinks.Console

Serilog.Sinks.Console is used instead of Serilog.Sinks.Literate now, which has been deprecated.

Here’s the code. The only real change is around the JsonFormatter

Log.Logger = new LoggerConfiguration()
   .WriteTo.Console()
   .WriteTo.RollingFile(
      new JsonFormatter(renderMessage: true), 
      "logs\\sample-{Date}.txt")
   .MinimumLevel.Verbose()
   .CreateLogger();

Log.Logger.Information("Application Started");

for (var i = 0; i < 10; i++)
{
   Log.Logger.Information("Iteration {I}", i);
}

Log.Logger.Information("Exiting Application");

Now, let’s add something new to this post, add the following NuGet package

  • Serilog.Settings.AppSettings

In my original post I pointed out that Serilog seemed to be aimed towards configuration through code, but the Serilog.Settings.AppSettings package allows us to use the App.config for our configuration.

Change you Log.Logger code to the following

Log.Logger = new LoggerConfiguration()
   .ReadFrom.AppSettings()
   .CreateLogger();

and now in your App.config, within the configuration section, put the following

<appSettings>
   <add key="serilog:minimum-level" 
        value="Verbose" />
   <add key="serilog:using:RollingFile" 
        value="Serilog.Sinks.RollingFile" />
   <add key="serilog:write-to:RollingFile.pathFormat"
        value="logs\\sample-{Date}.txt" />
   <add key="serilog:write-to:RollingFile.formatter" 
        value="Serilog.Formatting.Json.JsonFormatter" />
   <add key="serilog:using:Console" 
        value="Serilog.Sinks.Console" />
   <add key="serilog:write-to:Console" />
</appSettings>

This recreates our original code by outputting to both a rolling file and console output, bad sadly does not allow us to set the renderMessage parameter of the JsonFormatter.

Note: At the time of writing it appears there’s no way to set this renderMessage, see How to set formatProvider property in Serilog from app.config file.

Structured logging with the Semantic Logging Block

In another post I looked at Serilog and what structured logging capabilities can bring to an application, here I’m going to investigate the Patterns & Practices Semantic Logging Application Block.

So we’re looking at a means of logging more than just a “simple” string representing our state or failure (or whatever) from our application. Most likely we’re wanting to output log entries which can be analysed later in a more programmatic manner, i.e. querying or grouping log data.

Getting started

Let’s just get some simple code up and running to see how things fit together.

  • Create a console application
  • Using Nuget, add the following EnterpriseLibrary.SemanticLogging package
  • Add a new class named whatever you want, mine’s called MyEventSource

The MyEventSource class looks like this

[EventSource(Name = "MyEventSource")]
public class MyEventSource : EventSource
{
   public static MyEventSource Log { get; } = new MyEventSource();

   [Event(1, Message = "Application Failure: {0}", 
    Level = EventLevel.Informational,
    Keywords = EventKeywords.None)]
   public void Information(string message)
   {
      WriteEvent(1, message);
   }
}

Next up, let’s implement some simple logging code in our Main method

var eventSource = MyEventSource.Log;
var listener = ConsoleLog.CreateListener(
   new JsonEventTextFormatter(EventTextFormatting.Indented));

listener.EnableEvents(eventSource, 
   EventLevel.LogAlways, 
   EventKeywords.All);

eventSource.Information("Application Started");

// do something worthwhile 

eventSource.Information("Existing Application");

In the example code we’re logging to the console and using the JsonEventTextFormatter, so the output looks like this

{
"ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
"EventId": 1,
"Keywords": 0,
"Level": 4,
"Message": "Application Failure: Application Started",
"Opcode": 0,
"Task": 65533,
"Version": 0,
"Payload": {
"message": "Application Started"
},
"EventName": "InformationInfo",
"Timestamp": "2016-07-08T10:19:22.8698814Z",
"ProcessId": 20136,
"ThreadId": 19128
},
{
"ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
"EventId": 1,
"Keywords": 0,
"Level": 4,
"Message": "Application Failure: Existing Application",
"Opcode": 0,
"Task": 65533,
"Version": 0,
"Payload": {
"message": "Existing Application"
},
"EventName": "InformationInfo",
"Timestamp": "2016-07-08T10:19:22.9648909Z",
"ProcessId": 20136,
"ThreadId": 19128
},

Let’s now add a rolling file listener to our Main method

var rollingFileListener =
   RollingFlatFileLog.CreateListener(
      "logs\\semantic.txt", 1073741824,
      "yyyy.MM.dd",
      RollFileExistsBehavior.Increment, 
      RollInterval.Day,
      new JsonEventTextFormatter(EventTextFormatting.Indented));

rollingFileListener.EnableEvents(
   eventSource, 
   EventLevel.LogAlways, 
   EventKeywords.All);

So we simply attach another listener to our event source and now we are logging to both the console and a file (ofcourse in a non-sample application we would not be creating multiple JsoEventTextFormatters etc. but you get the idea).

That’s basically it – we’re up and running.

Structured logging with Serilog

Having used several .NET logging frameworks over the years, including the Logging Application Block, log4net, NLog as well as having used various logging frameworks in other languages.

In most cases the output to a log file is a formatted string, but in the past I’ve wondered about creating my logs in a way that could be queried or grouped in a more effective way. Recently this has become more relevant with a work project where we’re starting to use the ELK stack (Elasticsearch, Logstash & Kibana).

So I decided to take a look at some of the structured logging frameworks out there for .NET.

Getting started

I’m using Serilog 2.0, so obviously things may differ from his post with the version you’re using.

Let’s create a very simply console project to try this out on

  • Create a Console application
  • Using NuGet add Serilog
  • Using NuGet add Serilog.Sinks.RollingFile
  • Using NuGet add Serilog.Sinks.Literate

Now, we’ll jump straight into the code for this example

static void Main(string[] args)
{
   Log.Logger = new LoggerConfiguration()
      .WriteTo.LiterateConsole()
      .WriteTo.RollingFile("logs\\sample-{Date}.txt")
      .MinimumLevel.Verbose()
      .CreateLogger();

   Log.Logger.Information("Application Started");

   for (int i = 0; i < 10; i++)
   {
      Log.Logger.Information("Iteration {I}", i);
   }

   Log.Logger.Information("Exiting Application");
}

In this example, we use Serilog’s fluent interface to create our configuration. Whilst Serilog can be configured via a configuration file it appears it’s positioned more towards code based configuration.

Using the WriteTo property we can set-up one or more output mechanisms. In this case I’m using a console (LiterateConsole outputs nice coloured logs to the console), a RollingFile is created in the application’s folder off of the logs folder.

By default, Serilog sets it’s minimum logging level to Information, I’ve effectively told it to log everything by setting it to Verbose in the above code.

If we run this and view the output and/or log file, we’ll find the following output

2016-07-07 15:34:07.864 +01:00 [Information] Application Started
2016-07-07 15:34:07.906 +01:00 [Information] Iteration 0
2016-07-07 15:34:07.908 +01:00 [Information] Iteration 1
2016-07-07 15:34:07.908 +01:00 [Information] Iteration 2
2016-07-07 15:34:07.909 +01:00 [Information] Iteration 3
2016-07-07 15:34:07.910 +01:00 [Information] Iteration 4
2016-07-07 15:34:07.911 +01:00 [Information] Iteration 5
2016-07-07 15:34:07.911 +01:00 [Information] Iteration 6
2016-07-07 15:34:07.912 +01:00 [Information] Iteration 7
2016-07-07 15:34:07.912 +01:00 [Information] Iteration 8
2016-07-07 15:34:07.913 +01:00 [Information] Iteration 9
2016-07-07 15:34:07.913 +01:00 [Information] Exiting Application

As our purpose was to get queryable output, this doesn’t really help a lot, what we really want is a more structured format of output, like XML or JSON.

Let’s replace the .WriteTo.RollingFile line with the following

.WriteTo.Sink(new
   RollingFileSink("logs\\sample-{Date}.txt",
      new JsonFormatter(renderMessage: true), 1073741824, 31))

Now our log file output looks like this

{"Timestamp":"2016-07-07T15:42:35.2095535+01:00","Level":"Information","MessageTemplate":"Application Started","RenderedMessage":"Application Started"}
{"Timestamp":"2016-07-07T15:42:35.2695595+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 0","Properties":{"I":0}}
{"Timestamp":"2016-07-07T15:42:35.2725598+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 1","Properties":{"I":1}}
{"Timestamp":"2016-07-07T15:42:35.2735599+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 2","Properties":{"I":2}}
{"Timestamp":"2016-07-07T15:42:35.2735599+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 3","Properties":{"I":3}}
{"Timestamp":"2016-07-07T15:42:35.2745600+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 4","Properties":{"I":4}}
{"Timestamp":"2016-07-07T15:42:35.2745600+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 5","Properties":{"I":5}}
{"Timestamp":"2016-07-07T15:42:35.2755601+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 6","Properties":{"I":6}}
{"Timestamp":"2016-07-07T15:42:35.2755601+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 7","Properties":{"I":7}}
{"Timestamp":"2016-07-07T15:42:35.2765602+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 8","Properties":{"I":8}}
{"Timestamp":"2016-07-07T15:42:35.2765602+01:00","Level":"Information","MessageTemplate":"Iteration {I}","RenderedMessage":"Iteration 9","Properties":{"I":9}}
{"Timestamp":"2016-07-07T15:42:35.2775603+01:00","Level":"Information","MessageTemplate":"Exiting Application","RenderedMessage":"Exiting Application"}

We now have Json output – which I’m sure was obvious by the use of the JsonFormatter. The use of renderMessage : true (the default for this is false) ensures the output includes the rendered message as well as the MessageTemplate etc. The rendered message is equivalent to what the textual output would be.

Returning to our original code (the Main method) we have the following Log.Logger.Information(“Iteration {I}”, i);. You’ll notice we are using the placeholder {} syntax. The “I” within the {} could be named anything you want. It’s basically the property name uses in the Json Properties field. Ofcourse we can just as easily change this to something a little more meaningful such as

Log.Logger.Information("Iteration {Iteration}", i);

What is important though is to not fall into the trap of using a String.Format for this as this would lose the Iteration property name.

Adding context

Often we’ll want to log with some more context, for example what class we’re logging from, especially in situations where we might have similar output messages throughout our code. In such cases we can use the ForContext method

Log.Logger.ForContext<Program>().Information("Application Started");

this will cause our log file output to include the property SourceContext which a value of the namespace.classname for example

"Properties":{"Iteration":9,"SourceContext":"SerilogTest.Program"

Note: You might prefer to store the ILogger returned by Log.Logger.ForContext() instead of having the long line of code every time.

Clean disposal/completion of logging

Depending upon the logging mechanism used within Serilog, you may need to call the following when your application shutsdown

Log.CloseAndFlush();

this is especially relevent if the logging mechanism is buffered.

That’s it – straightforward, easy to use and now we can read the Json log files into some appropriately capable application and query or group etc. our log entries.