Category Archives: Logging

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.