Category Archives: Serilog

UWP Application’s file restrictions and logging

UWP applications have restricted access to the local file system and this can cause a few issues when using logging frameworks if you’re expecting to write logs to c:\Temp
or %Temp% locations (for example).

Your UWP application can write to the application’s installation folder, for example 

var installedLocation = 
   Windows.ApplicationModel.Package.Current.InstalledLocation.Path;

another alternatively is application data location, such as

var localFolder = 
   ApplicationData.Current.LocalFolder.Path;

// or

var localCache = 
   ApplicationData.Current.LocalCacheFolder.Path;

These last two location will translate to a location such as the following, where username is the (as you’d expect) username the user logged into the machine with, and the GUID is the package family name GUID (taken from the application’s manifest). This is actually an extended GUID. 

C:\Users\<username>\AppData\Local\Packages\<guid>

Note: At the time of writing I’m not sure where the string after the underscore which follows the GUID comes from.

Let’s take a quick look at using Serilog’s File Sink to write our log files. Using NuGet install Serilog and Serilog.Sink.File and use the following code

Log.Logger = _logger = new LoggerConfiguration()
   .WriteTo.File(
      new JsonFormatter(renderMessage: true),
      ApplicationData.Current.LocalCacheFolder.Path + "\\log.txt", 
      rollingInterval: RollingInterval.Minute)
      .MinimumLevel.Verbose()
      .CreateLogger();

References

File access permissions

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 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.