SL3 - Serilog Recipes and some advanced features

Let's explore some advanced features of serilog that we need in everyday programming

Wed, 20 Mar 2019

Banner

Welcome

I decided to share my knowledge about Structured Logging using 4 Post series in the hope that someone in community can benefits from it. I tried to make these post Beginner Friendly so if some experienced readers find it too basic/boring i apologies in advance.This is the third post in the series

All the posts from the series:

  1. All about structured logging - Introduction
  2. Getting Started with Serilog - Fundamentals
  3. Serilog Recipes - Templates, LogContext, Enriching Logs etc(This Post)
  4. Application Insights for Structured Logging

If you are beginner with the structured logging i highly recommend to have a read of the first post in the series. It’s about 5 minutes read. But it actually represent the use case for Structured Logging and how your applications can benefit from it in terms of monitoring and Dev-Ops aspect.Without any further delay let’s get started with the post.

I took about a week break between this post and last post because it was quite hard for me to decide a structure of this post information so that readers find it more natural or easy to understand. So let’s have a quick look at all the information that i will share with this post.

Agenda of the post:

  • Serialization
  • Message Templates and Properties (Some readers will prefer to read this before Serialization)
  • Context, Correlation and Enriching Logs

These are the few of the Serilog features that i use almost everyday while using serilog to write structured events from my applications. This post got dragged a little bit even after my best efforts to keep it concise. I hope you find it worth your time.

All the code examples used in this blog series can be found on it Github under the this Repo

Intro to Application Insights (If you want to follow along with code)

I was planning to delay the setup of Azure Application Insights till the last and the 4th post of the series. But then i realized it is important to have some Sink configured to demonstrate these advanced features of Serilog. So let’s create a application insights resource quickly. Please follow these steps if you want to run the code samples included with the post and see results for yourself. Otherwise you can skip it and we will do this configuration again in next post.

Step 1: Create free azure account using this Link

Step 2: Create Application Insight resource under your account using steps 1 to 3 from here.

Once you have the Application Insights resource created click on it to view details and the overview section should look something like.

ApplicationInsightsOverview

And you will be interested in the instrumentation key. Take a copy of it and configure your appsettings.json file with the instrumentation key value.

My config at this point looks like but i also use the combination of Code + Config File to configure logger:

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning"
    }
  },
  "ApplicationInsights": {
    "InstrumentationKey": "04cf998a-699a-469e-af3f-18e4c56d4b63"//will be deleted use your own key.
  },
  "AllowedHosts": "*"
}

Other configuration is configured using the Code configuration option of Serilog.

To check the above configuration run the code and hit the DummyController url https://localhost:44345/api/dummy/favorite in your browser and wait for may be 2-3 minutes then you should be able to see traces being recorded under the Search page of Application Insights.

There will be a delay between when code write logs to application insights and then they show up in the search console of Azure. This delay is introduced by ingestion of logging data by azure application insights. Stack Overflow Comment

This post is not about how to use Application Insights so i provided very basic instruction to configure more details about application insights in next post.Without any further delay lets get started with first topic for the discussion.

Serialization

Let’s have a look at one of the code examples from the past posts. This code is part of the DummyController.cs in the code files attached.

//... Removed code for readability

_logger.LogInformation("Returning car with RegistrationNo:{RegistrationNo} and {@CarInfo}", car.Registration, car);

//... Removed code for readability

If you look at the above statement it looks any typical logging statement except few things. One of them you may have noticed is @.

Serilog will serialize data before dumping if @ is used in front of hole placeholder.

And if it is some array or collection of strings it will automatically serialize you do not even need to mention the @ sign in front of it.

So in order to see the operator @ in action let check the Application Insights traces and what get logged.

Serialization Example 1

Few things to Notice:

  • We have user friend message as we logged as string under “Message”
  • Under custom properties we have property for “RegistrationNo”
  • We have property for “CarInfo”
  • “CarInfo” is serialized while logging

So if we break down things a little bit. Everything inside the {} curly braces with VariableName will get converted into Named custom property on the Traces logged and Values with @ and inside {} get converted in to named properties plus the values passed get serialized.

But why you want to store some values as Custom Properties on insights traces ?

Because if you create custom properties you can query logs using those custom properties. You can do something like this in application insight queries.

select * from logs where RegistrationNo = 'M5667' and timestamp > "2019-01-11T02:13:10Z"

This will return all the Log entries for a car registration number = M5667 after a particular date and time. Powerful isn’t it but more on queries in Next post of the series.

Next question is What about if you do not want to use the serialization provided by the serilog out of the box. You may have overriden the ToString for a class and want to use that instead. We can achieve that using $ sign instead of @ . So your code will change to 

_logger.LogInformation("Returning car with RegistrationNo:{RegistrationNo} and {$CarInfo}", car.Registration, car);

Destruct

If you want to control what properties of the object should be included in the serialization process then please check the Destruct section from the last post. That section explains the Destruct functionality in full details and various ways to get it done.

Scalars

As we understand few types like Email and Uri in .NET world are complex types with many properties but usually we are interested in the String value only. Instead of using $ in every logging statement we can do it globally. To store them just as string representation we can configure logger globally to always save their String representation.

.Destructure.AsScalar<EmailAddress>();

Request: Please be careful about the objects that you serialize using @ operator. If you serialize large nested objects. Then you can have some performance surprises.

Bit of summary of what we discussed about Serialization is

  • Use {} to created named custom properties.
  • Use @ to serialize the objects.
  • Use $ to use the ToString() representation of object.
  • Use Destruct to control what fields should be logged for an object.
  • Use AsScalar to configure logger globally to user String representation for a particular type(Eg: EmailAddress)

That was pretty much my knowledge about how to use Serialization features of Serilog. Now time to look at the next topic of discussion Message Templates and Properties.

Message Templates and Properties

This topic one of most brief topic from this blog post. But i still think it’s worth explaining all the capabilities that Message Template offer.

First of all what is message template. If you look at the screenshot above for a Trace entry there is a property under the custom properties called 'MessageTemplate and it looks like.

Message Template Example

It is exactly the string we used inside the logging statement so if we break it down.

Message Template:

"Returning car with RegistrationNo:{RegistrationNo} and {$CarInfo}"

Variables to replace:
car.Registration, car

Formatting options

Message templates are super set of the .NET strings. That means they can do everything that .NET strings are capable of. Plus some additional capabilities.

What does that mean you can use all String format capabilities of the .net Strings.

Few of them are:

  • {0:c} to format numeric value as currency (Ex: $27400.50)
  • {0:n} to format as thousand seperators (Ex: 27,400.50)
  • {0:x} to format as Hexadecimal

Beyond the standard numeric format strings, you can define your own specific formatting

For example:

  • {0:0000.0000} will format 3.45 to 00003.4500
  • {0:#####:##} will format 531.456 to 531.45

Then there is a plethora of options to format Dates and other data types provided by .NET string. For a extensive cheat sheet check this link

Why they matter?

Why the Message Templates worth a mention in this post because they are actually driving factor behind all the benefits of Structured Logging.

In conventional logger the when logging information is captured It is caputred Human Readable strings then if we need to extract parameters/properties for analysis and filtering. We do it by string parsing and extracting parameters/properties we are interested in.

Structured logging approaches data capture and formatting separately. In the structured logging workflow, capturing happens first while formatting an event into human-readable text is deferred until it’s needed later on,after any property-based filtering has been applied.

Steps in which information processed are:

  1. Take the description of an event and associated parameters
  2. Capture the description and parameter values
  3. Collect a serialized representation like JSON
  4. Filter based on parameters
  5. Format into human-readable text* (Using Message Templates)
  6. View matching events

Filtering using Message Templates

Moreover in application insights analytics we can search for logs entries using the message templates. As they are saved as custom properties on the traces. Below is a valid Azure Application Insights query that will filter and return Log entries by using MessageTemplate

-- Valid App Insights query
traces 
| where customDimensions.MessageTemplate == 'Returning car with RegistrationNo:{RegistrationNo} and {@CarInfo}'

I think this will help you have a basic understanding of the Message Templates and Properties. Let’s move to the next step Context and Correlation which is one of the most useful and important feature of Structured Logging.

Context and Correlation

In my opinion real power of Serilog as a structured logging come from the fact that it has such a nice api to add Contextual and Correlation information to your log entries.

What is correlation and why it is important (If already know please skip to next section)

Let’s first explain what does Correlation mean for the server applications. Why it is so important.

Consider a very simple Monolith web application with multiple layers. Something like that you can see on the left in the image below.

Application Layers

Most probably the end user request will land on the API Layer then the application layer call the Application Layer and then Application Layer will call further layers to process request.

Some information/context that you have available at the API Layer is not available in other layers. For example you have UserId available at the API Layer or RequestId is available at the API Layer inside your controller action. But once you call the Application Layer that information will be not available anymore. But you may want to include these additional info in log entries so you can track/correlate the same request by the user as it is processed through different layers of the applications.

Adding such information that actually help you relate/track requests across different layers/applications is called correlation.

In more complex scenarios your Web Application can be group of services (Micro Services or whatever) that work together to process end user requests. In that case you will have to track the same request across multiple services that make the application. But that discussion is beyond the scope of this post.

Different ways to add Contextual or Correlation information

There are mainly 3 ways(that i know of) to add Contextual or Correlation information to your logging entries.

  1. Contextual Loggers
  2. Ambient Contexts
  3. Globally attached properties

Contextual Loggers

This is the simplest way to add Context information to Logger. This is useful mainly to tag the Source of logs. You can do it once off while creating Logger instance and then every event logged using that instance will have these contextual properties.

For example you want to add Controller Name to the log statements generated by a controller code it can be as easy as 

Log.ForContext("Source", typeof(CartController).FullName)
    .Information("Adding {Item} to cart {CartId}", item, cart.Id);

ForContext method returns a logger that will attach the specified property to the events logged.

But to me that looks like lot of duplicate code for each controller. Don’t worry there is a better way to achieve this.

If you are using .NET core Dependency Inject you can inject Contextual Loggers simply like this.

        //DummyController.cs
        //Just constructor code
        private ILogger<DummyController> _logger;
        //Constructor where Logger will have contextual information about the Controller Name
        public DummyController(ILogger<DummyController> logger)
        {
            _logger = logger;
        }

Ambient Contexts

Within a unit of work such as a single HTTP request, or processing a message from a message queue, it’s useful to tag all events with a correlation identifier unique to the unit of work. Properties like RequestId or MessageId fit this pattern.

If use the Contextual Logger option we then have to account for passing the ILogger instance throughout request processing and make sure that all logging goes through the same instance . This can result in a lot of ILogger parameters on the various methods used during request processing.

To cater for this everyday requirement Serilog supports this use case through the ambient LogContext:

To use the ambient context you need to opt in at the configuration time of your logger how you do that ?

//something like this will help
 var loggerConfiguration = new LoggerConfiguration()
                .ReadFrom.Configuration(configuration)
                .Enrich.FromLogContext()//Opt in for Ambient Context Variable

So we will demonstrate this with a simple example. Where we have Endpoint on DummyController action named api/dummy/latest that will call some DummyService(Application Layer) method GetLatestCars and we will try to add RequestId to the ambient context so that we can add it to log statement inside the application layer.

So the Dummy Service look like:

//DummyService.cs
public class DummyService : IDummyService
    {
        private ILogger<DummyService> _logger;
        //Getting it's own version of Logger
        public DummyService(ILogger<DummyService> logger)
        {
            _logger = logger;
        }

        /// <summary>
        /// Just a dummy method to return a list of cars.
        /// </summary>
        /// <param name="count"></param>
        /// <returns></returns>
        public List<CarDto> GetLatestCars(short count =10)
        {
            _logger.LogInformation("Inside Service: User request to Fetch {Count} latest cars", count);
            var range = Enumerable.Range(1,count);
            var cars = new List<CarDto>();
            foreach (var item in range)
            {
                cars.Add(new CarDto
                {
                    EngineNo = $"ENG1234{item}",
                    Make = $"Toyota{item}",
                    Model = $"{2014+item}",
                    Registration = $"M228{item}"
                });
            }
            //DO NOT LOG EVERYTHING ON PRODUCTION IT FOR DEMO PURPOSES
            _logger.LogInformation("Inside Service: GetLatestCars returned {@Cars}", cars);
            return cars;

        }

Then we setup the New DummyService for .NET Core dependency injection.

//Startup.cs

//Register our Dummy service to call
            services.AddTransient<IDummyService, DummyService>();

Now time to update the DummyController to Use our shiny new DummyService to get the data. Let’s look at how the controller constructor will be changes to inject the service.

//DummyController.cs
//...Removed code for readability
        private readonly ILogger<DummyController> _logger;
        private IDummyService _dummyService;
        public DummyController(IDummyService dummyService, ILogger<DummyController> logger)
        {
            _logger = logger;
            _dummyService = dummyService;
        }

Now we will look at how we can use the new DummyService inside a controller action.

//Actual action to get latest cars
        [HttpGet]
        [Route("latest")]
        public ActionResult GetLatestCar()
        {
            //it can be anything i am using some random value as context variable like UserId or something 
            using (LogContext.PushProperty("ApiRequestId", Guid.NewGuid()))
            {
                _logger.LogInformation("Inside Controller: User request to fetch the Favorite car");
                var cars = _dummyService.GetLatestCars(10);
                return Ok(cars);
            }
        }

So if we look at the above I pushed the parameter ApiRequestId to ambient context with using block as a result we should see the same value of ApiRequest parameter for traces logged inside the Controller action and inside the DummyService method.

We have these logging statements

//Inside controller (Controller Trace)
 _logger.LogInformation("Inside Controller: User request to fetch the Favorite car");

 //Inside the DummyService (Service Trace 1)
_logger.LogInformation("Inside Service: User request to fetch the latest car");
//(Service Trace 2)
_logger.LogInformation("Inside Service: GetLatestCars returned {@Cars}", cars);

Let’s hit the https://localhost:44345/api/dummy/latest in the browser. Then go to Application Insights and check for the traces recorded.

For the Controller Trace we recorded:

Controller Trace

For Service Trace 1 We recorded

Controller Trace

For Service Trace 2 We recorded

Controller Trace

If you look carefully you can see all of these traces have the ApiRequestId custom property with same value. We just added a variable to the ambient context from controller and it was maintained through the whole call hierarchy no matter how deep the call stack is.

I think it is enough regarding the context and correlation to get you started and you can explore more in your own adventures. Let’s move on to the next item on the list Globally attached properties.

Globally attached properties

Few common pieces of information that we mostly add to context as correlation information. To identify which Application, which environment and which specific request failed or took too long to process.

  • Machine Name - Server Machine Name(To find out incase only one of the machines in server farm is having issues)
  • Environment - Ex: Prod, Staging, UAT etc
  • Application - Name of the application
  • Request Id - So we can track all the events raised by the same request.

As you want this information to be added to almost every logging event so you must prefer to do it globally and every logger instance just inherit that.

You can attached the properties at the configuration time.

Log.Logger = new LoggerConfiguration()
    .Enrich.WithProperty("Application", "e-Commerce")
    .Enrich.WithProperty("Environment", ConfigurationManager.AppSettings["Environment"]);

There are few pre-built Enrichers that can help you configure such global Properties

Few enrichers are

using these pre built enrichers are pretty easy to use it can be as simple as:

//using Serilog-enricher-environment.
.Enrich.WithMachineName()

There are many other amazing enrichers out there that you can use. But in case you don’t want something you want you can create your own enricher and its pretty easy to do so.

//our shiny and useless new enricher
//But i think you got my point
class NerdLifeEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        logEvent.AddPropertyIfAbsent(
            propertyFactory.CreateProperty("Remember", "LiveFullStack", false));
    }
}

//How to use it now?

 Log.Logger = new LoggerConfiguration()
    .Enrich.With(new NerdLifeEnricher())

Time to say goodbye (+Shameless Plug)

In this post we discussed few recipes with Serilog and some of its impressive features. Time for me to say goodbye but i will see you guys soon with another post (Last of the Series). Till then bye and take care.

If you like my posts remember your words of appreciation goes long way in inspiring me to keep writing. If you do not want to miss any of my Future posts follow me on Twitter

SHARE
Ranjeet Singh

Ranjeet Singh Software Developer (.NET, ReactJS, Redux, Azure) You can find me on twitter @NotRanjeet or on LinkedIn at LinkedIn