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 boring i apologies in advance.This is the first post of series.

All the posts from the series:

1. All about structured logging - Introduction
2. Using Serilog for structured logging - Fundamentals(This Post)
3. Serilog Recipes - Templates, LogContext, Enriching Logs etc
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. It represent the use case for Structured Logging and how your applications can benefit from it in terms of monitoring and from Dev-Ops aspect.

What is covered

As Serilog is a big topic and have too many useful and amazing features and I find it really difficult to cover each of them in a single post so i will be writing 2 posts to discuss feature of Serilog but still it far from complete guide.I tried to discuss all the features that i used frequently in applications that i worked on.

I tried to divide information into small topics so that you can stop and resume later. Topics Covered in this post:

• How to configure serilog for .net core applications
• What are serilog Sinks.
• Logging structured data to a text file.
• How to destruct object and log.

I am very new to blogging and will be great if you can provide feedback about if breaking information into topics instead of series of paragraphs helps the reader in understanding the post. I usually tries to keep post concise and at most 5 minute reads per post. But if it goes beyond that you can use these topics as sort of bookmarks to keep track where you left.

If you want to code along or need code files to have a look at it later. Then the code files for this blog post can be found here in a github project LINK.

Configure Serilog for .Net Core Applications

I created a project using the default .NET Core Web Application project template in Visual Studio and then started editing the basic project. Let’s start with the Program.cs that we got from the default project template and we will keep editing stuff as we progress.

First things first we will need to install the required Nuget packages for the Serilog and Sinks that we are interested. List of nuget packages that i added to project for logging is

    <PackageReference Include="Serilog.AspNetCore" Version="2.1.1" />
    <!-- To configure logger from configuration files -->
    <PackageReference Include="Serilog.Settings.Configuration" Version="2.6.1" />
    <!-- To use application insights as sink for our logger -->
    <PackageReference Include="Serilog.Sinks.ApplicationInsights" Version="2.6.0" />
    <!-- To use console sink for our logger -->
    <PackageReference Include="Serilog.Sinks.Console" Version="3.1.1" />

We can configure the Serilog either using the code or using the application configuration files(appsettings.json). Both approaches have their own downsides and benefits it’s hard to choose the universal best practice for this so i will show both the approaches using the code and using the Configuration files. You can choose whatever you feel is best fit for your applications.

First let’s have a look at the code example then we will look at the config file example later. Here is the Program.cs from the code files attached to the blog post. I added some extra comments to help with the understanding the code sample.

            //We create instance of the logger configuration using fluent api
            //This api is provided by serilog nuget package.
            //We create very simple configuration that create a logger that write to console
            var loggerConfiguration = new LoggerConfiguration()
                .Enrich.FromLogContext()//More on LogContext later
                .WriteTo.Console();//Write log data to console sink
            //Create the Logger Instance and assign to Logger Factory
            Log.Logger = loggerConfiguration.CreateLogger();

            //... Omitted lot of code to just focus on something we are interested

So we observed how easy to it is to getting started with Serilog in your .Net Core applications. But lot of people don’t like the code configuration because in case you want to change minimum logging level or want to add an additional Sink to your logger configuration you will have to make changes to your code and then do a new build and deploy the new build. For some of us that is too much of an effort so they prefer to configure the logger using the config file like appsettings.json in that case they can change configurations on the fly and Serilog behavior will change.

Now we will look at the configuration file and some C# that help us achieve something similar to above configuration. First we create the required configuration changes in the appsettings.json file then we will change code.

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.ApplicationInsights" //Write logs to application insights
    ],
    "MinimumLevel": {
      "Default": "Debug", //Minimum logging level is debug
      "Override": {
        "Microsoft": "Information"// But Minimum level is overriden for all Microsoft Libraries including Framework itself.
      }
    },
    "WriteTo": [
      {
        "Name": "ApplicationInsights", 
        "Args": {
          "instrumentationKey": "YOUR-KEY",//Instrumentation key for application insight resource Ignore for now
        }
      }
    ],
    "Enrich": [ "FromLogContext" ],//Ignore this for now
    "Properties": {
      "Application": "Sample"//Name of your applications.
    }
  }
}

I understand the the config file setup is not very readable and looks like it will be really hard to handcraft this sort of configurations i acknowledge that it looks hard to configure. But if you tackle olne thing at once it becomes lot more easier. Anyways here is an example if someone want to use the appconfig.json file to configure your serilog logger.

Time to look at the sinks for serilog and what purpose they serve.

What are serilog sinks

Bit of a recap of the first post introduction of Sinks. Sinks are nothing special it’s just where you persist you structured logging data for later analysis. It can be as simple as some File system file or it can some 3rd party application that is designed to stored structured events for analysis and examples that i used in the past are Seq and Application Insights.

If i try to draw a very simple diagram how your application code, Serilog and Sinks fit together.The picture will look like something below.

I am no architect so please do not expect this diagram to be inline with best practices and architecture patterns.

It is just to explain how sinks fit in the whole ecosystem.

As we can see in the diagram that we can register multiple Sinks to single serilog logger and all the Sinks will get the data. We can define Sink specific setting for Serilog for example you want to filter out logs or define different logging levels for different sinks. Let’s have a quick look at how you can do it.

Again we can configure Sink specific overrides using both the code and appsettings.json config files so we will quickly look at the both examples. I tend to use simple examples to keep the posts beginner friendly so most probably these examples will not look like some complex real-world application scenarios.

Here we go and look at the code example first. Code credit to Serilog Guide on Github

//Default level is debug but for console we make sure the minimum logging level is Information
Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .WriteTo.File("log.txt")
    .WriteTo.Console(restrictedToMinimumLevel: LogEventLevel.Information)
    .CreateLogger();

//if we want even finer control what a Sink should see
//Serilog got a fluent api to allow configure sub loggers
Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    //For writing to File Sinks We want to filter all the log entries
    //Where value of "Count" property in logging information is Less Than 10
    .WriteTo.Logger(lc => lc
        .Filter.ByIncludingOnly(Matching.WithProperty<int>("Count", p => p < 10))
        .WriteTo.File("log.txt"))
    .CreateLogger();

//You can do all sort of fancy stuff using the combination of the fluent api and Predicates.

Now we will look at how you can do something similar if you are using appsetting.json file for configuration of the logger. Just a heads the JSON looks hard to read but that’s price we have to pay for flexibility i think.

Code Credit to Github issues for Serilog Project.

{
  "Serilog": {
    "Using":  ["Serilog.Sinks.Literate"],
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "Microsoft": "Warning",
        "MyApp.Something.Tricky": "Verbose"
      }
    },
    "WriteTo": [
      {
        "Name": "LiterateConsole",
        "Args": {
          "restrictedToMinimumLevel":"Information",//Overriding the Minimum Level logging to Information from Default of Debug
          "outputTemplate": "[{Timestamp:HH:mm:ss} {SourceContext} [{Level}] {Message}{NewLine}{Exception}"//Sink specific template
        } 
      },
      {        
        "Name": "File",
        "Args": {
          "restrictedToMinimumLevel":"Debug", //Use the Debug as minimum level for File Logger
          "path": "serilog-configuration-sample.txt",//Sink specific param
          "outputTemplate": "{Timestamp:o} [{Level,3:u}] ({Application}/{MachineName}/{ThreadId}) {Message}{NewLine}{Exception}"//Sink specific template for the message
        }
      }
    ],
    "Enrich": ["FromLogContext", "WithMachineName", "WithThreadId"], //Serilog Enrichers more on this later in next post
    "Properties": {
      "Application": "Sample" // Name of your application 
    }
  }
}

This is a very basic example of how you can use the Args section of each sink configuration to pass override parameters for configuration. The question that straightaway come to mind is the what are all possible values for these Args. Actually this question is hard to answer there are few common params like restrictedToMinimumLevel but there are Sink specific Args also. Best way to find out is to look at the documentation of each Sink. They are basically parameters to the Sink constructor. So the best place to look is the documentation for the given Sink.

Don’t worry about the extra stuff in the config rules. We will discuss all of these configuration one by one. Let’s tackle one thing at a time.

That’s pretty much regarding the Sinks for the Serilog. I hope it will help you get started and best of luck with your future adventures.

Logging structured data to text files

We are going to take things easy and as a first example we will basically configure a Serilog logger and use File as the sinks for our Serilog Logger and we will try to log some simple user friendly messages and also some structured messages to the Files and see how they look different. If you already have downloaded the Code files for this blog post you can check. DummyController as you can see we inject the logger using Constructor Dependency Injection then use it in our controller actions.

First have a look at the Serilog configuration we have in place. To improve readability i am using Code version of the configurations. We will configure the Logger to use the File Logger. I tried to put all the possible Serilog configuration into one file in code attached i hope it will make easy for readers to find all the Serilog configurations we used in this post. File where i added all the Serilog configurations is LoggerConfigurations.

//Inside the file LoggerConfigurations.cs
 public static ILogger ConfigureFileLoggerUsingCode()
        {
            var loggerConfiguration = new LoggerConfiguration()
                .WriteTo.Console() //More on LogContext later
                .WriteTo.File("Logs.txt", LogEventLevel.Debug)
                .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)//Override for framework libraries
                .MinimumLevel.Override("System", LogEventLevel.Warning);// Override to avoid logging system INF events
            return loggerConfiguration.CreateLogger();
        }


// Now how we assign this logger to our Logger Factory 
//We go to program.cs and then inside Main function we do something like
Log.Logger = LoggerConfigurations.ConfigureFileLoggerUsingCode();

Now we have configured the Serilog logger and Assigned it to the Logger Factory instance. Next question how we use it in our controllers or services. We will rely on the Dependency Injection provided by .NET CORE out of the box and we will use constructor dependency injection in our example.

For this example if you have copy of the code for this post. Check Api/DummyController.cs

//We use the dependency injection to inject logger 
        private ILogger<DummyController> _logger; //Contextual Logger 
        //Injecting contextual logger
        public DummyController(ILogger<DummyController> logger)
        {
            _logger = logger;
        }

//Next step is to use this logger to log information 
//Then verify the information is written to text files "Log.txt" at the root of project

//Created a dummy method that will return a car information 

//Dummy action to return a single car 
        [HttpGet]
        [Route("favorite")]
        public ActionResult GetFavoriteCar()
        {
            _logger.LogInformation("User request to fetch the Favorite car");
            var car = new Car()
            {
                EngineNo = "Eng987",
                Model = "TT",
                Make = "Audi",
                Registration = "R1234"
            };
            //we are using the Logger to log information like conventional logger
            _logger.LogInformation($"Returning car with RegistrationNo {car.Registration} and CarInfo {car}");
            //Now we are using the Serilog feature to log Named properties and Automatic serialization using @ symbol
            _logger.LogInformation("Returning car with RegistrationNo:{RegistrationNo} and {@CarInfo}", car.Registration, car);
            return Ok(car);
        }

//Go to browser and hit url /api/dummy/favorite it should return json response

Now we try to hit the above url using our browser so we can see the Logger in action. Our url for this action on the Dummy Controller should be something like https://localhost:44345/api/dummy/favorite.

When type the above url in the address and hit enter we should get some JSON response back. But lets see what information is logged for the above request. I added some comments below using square([]) brackets they will not be in the resulting log files.

2019-03-14 15:40:24.284 +11:00 [INF] Starting web host -- [Logged by main function in program.cs]
2019-03-14 15:40:38.761 +11:00 [INF] User request to fetch the Favorite car -- [First log entry inside controller action]

[we are using the Logger to log information like conventional logger]
2019-03-14 15:40:38.767 +11:00 [INF] Returning car with RegistrationNo R1234 and CarInfo AllAboutLogging.Models.Car 

[Now we are using the Serilog feature to log Named properties and Automatic serialization using @ symbol]
2019-03-14 15:40:38.778 +11:00 [INF] Returning car with RegistrationNo:R1234 and {"Registration":"R1234","Make":"Audi","EngineNo":"Eng987","Model":"TT","$type":"Car"}

As you can see using @CarInfo caused the second parameter ‘car’ to be serialized in case. Where as in first logging statement using car directly in string template just call the ToString of the object and that resulted in the Type Name for the car parameter.

This was just an example how we can easily configure the Serilog to write log to text files. When configuring File sink you can also configure Rolling File settings. What should be the maximum size for each log file and many maximum files to keep. Let’s have quick look how we can configure the Rolling Files using Serilog configuration.

//Configure simple file and console logger but also enable rolling files 
        public static ILogger ConfigureFileLoggerWithRollingFilesUsingCode()
        {
            var loggerConfiguration = new LoggerConfiguration()
                .WriteTo.Console() //More on LogContext later
                //fileSizeLimitBytes: We instruct that Limit each log file to 10 MB
                //rollOnFileSizeLimit: We instruct to create new file when the size is exceeded 10MB
                //retainedFileCountLimit: We instruct to keep maximum of 20 logs files
                .WriteTo.File("Logs.txt", LogEventLevel.Debug, fileSizeLimitBytes: 10485760, rollOnFileSizeLimit: true, retainedFileCountLimit: 20)
                .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)//Override for framework libraries
                .MinimumLevel.Override("System", LogEventLevel.Warning);// Override to avoid logging system INF events
            return loggerConfiguration.CreateLogger();
        }

There are other few settings also available for the File but i will leave you to have a play with it on your own. I hope this basic introduction to serilog logging to text files will help you to get started and start exploring the amazing Serilog and what i can offer. This is the wrap of Logging to text files lets move on to the next topic of the post.

How to destruct objects and log

This is the last topic of this post and it’s related to a very interesting scenario that you may face in your application. As we already looked at the @ operator and when we use it with Serilog it will serialize the object passed and log it to your logs.

Be careful! When you are using @ to log objects. Because it can result in trouble easily. You must know what you are doing what kind of object you are logging. Logging really big objects with nested structures can results in performance Surprises. Logging objects sometimes can alsoresult in writing sensitive information to plain text logs. So please take caution while using this feature.

Sometimes you don’t want to log whole object and want to exclude few of the fields from getting logged. Let’s talk about a possible real world LIKE scenario (Still Imaginary) Consider you have a logging statement inside logging action/function and you log the full model data posted by the client using the @.

This approach will have one problem this payload will have Password of the user or some other sensitive information. You want to log the request information but you want to exclude few of the sensitive fields from the payload.

I think a code example will make things a bit more clear. So what we want to achieve is when we log the Login request information for a user we do not want to skip logging Password.

Here is what our controller action looks like

//Inside HomeController.cs
public IActionResult Login(LoginModel model)
        {
          //We want to all LoginModel properties
            _logger.LogInformation("Requested login  for {@User} from address {IpAddress}", model, Request.HttpContext.Connection.RemoteIpAddress);
            return View();
        }

There are three ways you can do it as per my knowledge. Each approach have it’s own benefits and shortcomings. But i will leave it up to you decide which one works best for you.

Method 1: In this method we will configure the object Destructuring or transforming at the Logger configuration time. So you a possible logger configuration can look something like.

//Configure simple file and console logger but also enable rolling files 
        public static ILogger ConfigureLoggerWithDestructure()
        {
            var loggerConfiguration = new LoggerConfiguration()
                .WriteTo.Console() //More on LogContext later
                //fileSizeLimitBytes: We instruct that Limit each log file to 10 MB
                //rollOnFileSizeLimit: We instruct to create new file when the size is exceeded 10MB
                //retainedFileCountLimit: We instruct to keep maximum of 20 logs files
                .WriteTo.File("Logs.txt", LogEventLevel.Debug)
                .Destructure.ByTransforming<LoginModel>(login => new {login.Email, login.RememberMe})// We tell serilog to skip Password while serializing
                .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)//Override for framework libraries
                .MinimumLevel.Override("System", LogEventLevel.Warning);// Override to avoid logging system INF events
            return loggerConfiguration.CreateLogger();

One immediate problem i see with this approach is configurations can become complex in real world where you have 100s of models and sometimes they belong to different Nuget Packages/projects and defining them in you Logger configuration create sort of coupling that i don’t like that much.

Method 2: This approach is more flexible in my opinion but result in writing more code and becomes really hard when you have Nested object structure. You can define which fields you want to serialize right in the logging string template.

//So this original Logging statement
_logger.LogInformation("Requested login  for {@User} from address {IpAddress}", model, Request.HttpContext.Connection.RemoteIpAddress);

//Will change to 
_logger.LogInformation("Requested login  for {@User(Email, RememberMe)} from address {IpAddress}", model, Request.HttpContext.Connection.RemoteIpAddress);

Method 3: This method involved includes adding additional dependency to your project. The package name is Serilog.Extras.Attributed so i installed the package using Nuget. Then all i had to do was to add attributes to LoginModel and new model looks something like.

public class LoginModel
    {
        [Required]
        [EmailAddress]
        [Display(Name = "Email Address")]
        public string Email { get; set; }

        [Required]
        [Display(Name = "Remember me")]
        public bool RememberMe { get; set; }

        //Skip password while logging
        //Provided by Serilog.Extras.Attributed
        [NotLogged]
        [Required]
        [DataType(DataType.Password)]
        public string Password { get; set; }
    }

Now the code looks lot more cleaner there something that i don’t like about this approach. Logging is a cross cutting concern and Models should not worry about what Logging library or mechanism we are using when use these Serilog specific attributes in models it add extra responsibility on Models and this responsibility should not be taken care by Models in my opinion. but that’s just my opinion about this approach.

So i leave it upto you to decide which one of these method is your favorite.

Time to say goodbye (+Shameless Plug)

In this post we introduced Serilog and looked at few ways we can integrate with our .NET Core applications.This post was just a teaser of what Serilog is capable in next post we will discuss more advanced features and recipes with Serilog in .NET Core applications. Time for me to say goodbye but i will see you guys soon with another post. 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 my future post follow me on Twitter.