Looking into Structured Logging with Serilog in an ASP.Net Core application

In this blog post I am going to look into logging and more specifically into structured Logging. There is no need to stress how important logging is in any .Net application.

I am going to talk about structured Logging with Serilog and Seq. I am going to create an ASP.Net Core application to demonstrate logging with Serilog.

Let me give you a definition what structured logging is before we go any further.

Structured logging is a way of logging where instead of writing just plain text data to our log files we actually write meaningful log data by writing properties that are relevant to our application and values for those properties. This is a huge plus because now that we have structured  data we can go on and write queries against.

Logging to a text file, we log all sorts of information. We have different levels of information like warnings, errors, critical messages e.t.c. Ιn order to get some meaningful information out of it we have to use external tools or use regular expressions. In many cases we have logged data which is written in many log files. As you can understand in order to get the data we want, we need either to merge all those files or run the same regular expressions across all the files.

With structured logging we can have different queries, more intelligent queries. We can query and get data for a particular order, we can get error log messages where order value is more thatn 5.000 USD. We could get data regarding failed login attempts.

One of the most important logging libraries is the Serilog logging library. When building your application, you can install the Serilog NuGet package and once you have installed this NuGet package you can start writing simple log messages. These could be messages such as information messages or more important error messages, and when you configure Serilog in your application you can decide where you want our log output to be be written to.

We could write to rolling text files, so this means a new text file will be created automatically each day or we could write our log messages to a NoSQL data store like RavenDB or Seq.We can configure multiple destinations to be used by the same logger, so when we write a log message it will automatically be written to multiple output stores.

When we’re using Serilog there’s a number of different places we can write our application log data to,  such as the console, rolling files or single files.We can also write log data to MongoDB, RavenDB and Seq. I have mentioned Seq a few times so let me explain what Seq is.

It runs as a Windows service and it allows us to configure our applications, via Serilog, to log structured messages to it via HTTP or HTTPS. When our applications log structured messages to Seq server it stores  named properties/values so we can query them later. As part of the Seq server Windows service, it also provides a web interface, so we can connect to it via a browser. This browser application allows us to view log messages and write queries against them.

You can download Seq here.

Follow the instructions of the wizard to install the Seq windows service. When you install it you must see something similar like the picture below. The default port for listening to events in Seq is 5341 but in my case I choose 5343 port.

 

Before we begin with our hands on example I must dive into the mechanics of Serilog.

Besides information messages we can log structured data using Serilog. We can do that by using named properties and values e.g

Log.LogInFormation (“Added user {Username}, Team {UserTeam}”, name, team);

You can see between the braces here we’ve got this UserName and Team and these are named properties in Serilog.

When we define Named Properties we need to give them some values, so after we’ve defined the message containing these named properties, we then specify the actual values for the name and the team.

When we embed structured data in our message here, if the underlying sink supports it, these named properties and their associated values will actually be stored in the underlying data store allowing them to be queried. If you want to see all the available sinks currently supported click here.

Serilog has a number of different concepts of data types, the first or what it defines as scalar data types. Serilog sees these scalar data types as things that can be reliably stored without needed to alter their representation in any way. The types of scalar data include Boolean, numbers, strings, dates and times, as well as a few other things.

In the Boolean category we’ll just have the bool type. In the numbers category we have the basic numbers.

In the string category we have our string type and for dates and times we have the DateTime, DateTime Offset, and TimeSpan types. For the others we have Guids, URIs, as well as nullable versions of these other scalar types, so when Serilog sees that we’re using one of these values for a named property it’ll just go ahead and store its basic representation without doing any further processing on the value.

As well as scalar values, Serilog will store collections and objects. If the type implements IEnumerable it will go ahead and iterate through the contents of this IEnumerable and store the values. Serilog will also store the contents of a dictionary for us, but with a caveat that the key to the dictionary must be one of the types that Serilog considers to be scalar, so here the key to the dictionary is a string type.

Now that we have a good understanding of structured logging and Serilog, we can create a simple ASP.Net Core application. Launch the VS 2015 Studio and create a default ASP.Net Core Web application. Build and run the project.

The application out of the box should look something like this

 

I am going to install some packages now.

I will install Serilog, Serilog. Extensions.Logging and Serilog.Sinks.Seq

I will use the Package Manager Console to do that. Have a look at the picture below.

 

We need to do some configurations in the Startup.cs file.

 

public class Startup
{
public Startup(IHostingEnvironment env)
{
var builder = new ConfigurationBuilder()
.SetBasePath(env.ContentRootPath)
.AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
.AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true)
.AddEnvironmentVariables();

if (env.IsDevelopment())
{
// This will push telemetry data through Application Insights pipeline faster, allowing you to view results immediately.
builder.AddApplicationInsightsSettings(developerMode: true);
}
Configuration = builder.Build();
Log.Logger = new LoggerConfiguration()
 .MinimumLevel.Debug()
 .Enrich.FromLogContext()
 .WriteTo.Seq("http://localhost:5343")
 .CreateLogger();
}

I added the lines in bold in the Startup class.

I also need to add a line of code in the Configure method also in the Startup.cs file.

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
loggerFactory.AddConsole(Configuration.GetSection("Logging"));
loggerFactory.AddDebug();
loggerFactory.AddSerilog();

app.UseApplicationInsightsRequestTelemetry();

if (env.IsDevelopment())
{
app.UseDeveloperExceptionPage();
app.UseBrowserLink();
}
else
{
app.UseExceptionHandler("/Home/Error");
}

app.UseApplicationInsightsExceptionTelemetry();

app.UseStaticFiles();

app.UseMvc(routes =>
{
routes.MapRoute(
name: "default",
template: "{controller=Home}/{action=Index}/{id?}");
});
}

I added the line in bold to add Serilog to the ILoggerFactory that is passed into the Configure() method.

Now if we build and run the application again, in the Seq browser window interface we will see something like the picture below.

All the events (all detailed events until the Home page is fully served) are logged with Serilog and we can see them in Seq. We can search through them very easily. Have a look at the picture below.

 

 

In order to use Serilog to log our custom events we simply need to start logging from our own controllers.

In my sample application so far I have only the Home Controller. In order to start logging from my controller is to create an instance of dependency on type ILogger<T>

public class HomeController : Controller
{

readonly ILogger<HomeController> _logger;
 public HomeController(ILogger<HomeController> logger)
 {

_logger = logger;
 }

public IActionResult Index()
{
 _logger.LogInformation("Hello, world!");
return View();
}

public IActionResult About()
{
ViewData["Message"] = "Your application description page.";

return View();
}

public IActionResult Contact()
{
ViewData["Message"] = "Your contact page.";

return View();
}

public IActionResult Error()
{
return View();
}
}

 

I have added some lines (in bold). Build and run your application. Switch to the Seq browser window and search for “Hello”.

Have a look at the picture below.

 

We can pass an object as a property that is of type IEnumerable. Serilog will treat this property as a collection.

public IActionResult Index()
{
var team = new[] { "Panathinaikos", "Barcelona", "Liverpool" };
 _logger.LogInformation("My fav team is {Team}", team);
_logger.LogInformation("Hello, world!");
return View();
}

I added some lines in bold below in the Index method of the Home Controller.

Build and run the project again.

When I switch to the Seq browser window I see something like the picture below.

 

Let me create a simple class object and log its values.

Firstly, create a folder “Models” in your project. Then add the following class in it.

 public class ContactModel
 {
 public string Name { get; set; }
 public string Surname { get; set; }
 public string Email { get; set; }
 }

Then inside the Index method of your HomeController.cs add the code (in bold)

public IActionResult Index()
{
//var team = new[] { "Panathinaikos", "Barcelona", "Liverpool" };
//_logger.LogInformation("My fav team is {Team}", team);
//_logger.LogInformation("Hello, world!");

var contact = new ContactModel();

contact.Name = "Nick";
 contact.Surname = "kantzelis";
 contact.Email = "nikolaosk@admin.com";

_logger.LogInformation("Contact Name is:{@ConctactModel}", contact.Name);

return View();
}

Build and run the project again.

When I switch to the Seq browser window I see something like the picture below.

 

There are different logging levels available to us in Serilog. We can use verbose events to log very low-level debugging and internal information about what our code’s doing. Then we have debug level of events, to log events related to the control logic, so which modules or branches of the application are being used, as well as diagnostic information that might help us diagnose faults, but not necessarily as low-level as the verbose events.

We can think of the information level events  as the ability to log events that are of some interest to external parties, so these high-level events could be something like a user has just placed an order for a certain value.

Next, we have the warning level events. We can use this level to log information about potential problems that may be occurring in the application, so even if the system is not currently experiencing any actual errors, we can use this log level to give us advanced warning about things that could potentially break in the future.

Next, we have the error level events and these errors allows us to log information about unexpected failures in the system, so if there’s been an error in the system, but we’re still able to continue running the system, we could use this error level event. If, however, a failure has occurred and it’s actually stopped the system from being able to process any more information, we can use the fatal level event. This level of event allows us to log information about critical system failures.

There are various ways you can format your messages as we saw earlier in our examples.Formatting is another great strength of Serilog.

You can also log events selectively by using filters. For example we could write something like that

Log.Logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.Enrich.FromLogContext()
.WriteTo.Seq("http://localhost:5343")
.Filter.ByExcluding(Matching.WithProperty<int>("Count", c => C > 30))
.CreateLogger();

In this post we looked into structured logging, Serilog, sinks, Seq, data types supported by Serilog, formatting options of Serilog and filtering capabilities of Serilog.

Hope it helps!!!