Logging in ASP.NET Core

Intro

As a Developer there is no feeling that compares to the mix of emotions we experience after developing our application: relief, excitement, delight, and occasionally even tears (tears of joy). Because we have put our time and hard work into developing a fully functional application to solve a problem.

In the development stage, we want to ensure our application runs perfectly without a bug. We tested our application by running it in debug mode and verifying all features work as expected, or maybe you have created a unit test and integration test for the project and ensured all running tests passed.

Then we are ready to move to the next stage to ship our code into production, we deploy the application, and we think that our task is done. After a while, users of our application report that they encounter an error when using our application. It feels bummer, right? We have made sure that our code doesn't have bugs, and now it seems hard to identify the root cause of the problem because we cannot use debugging mode in production.

You must know that in a production environment, something can go wrong that isn't directly caused by your code, issues can arise from this unexpected error such as network timeouts, database connectivity issues, or third-party API failures.
The question is how to identify this problem that can arise in our running application in a real-time. Logging come to the rescue

Logging

Logging is recording all the events that occur in our running application. It can create a log message of error or maybe just information on execution flow. These log messages can be saved and looked at in various destinations such as the console, file, database, monitoring tool, etc.

The real question is: what is the best approach to creating logging into our apps? Are you still creating a logging mechanism by creating a file and writing a text in the file manually by yourself? 

My best advice is to never manually create a logging system. It's a waste of time, and it might not have a great capability like a logging framework can offer, like structured logging (we'll talk more about the latter). In ASP.NET Core, there is a built-in logging framework that is auto-enabled, and you can use it right away. Before we create our user-defined log message, you must know several log levels indicate the severity of events in your application, there are: 

• Trace: Use for highly detailed, step-by-step diagnostic information.
• Debug: Use for development and debugging purposes, logging detailed internal state information.
• Information: Use for general operational events that provide insight into the application's normal behavior.
• Warning: Use for issues that may not be immediately harmful but could lead to problems if not addressed. Like in the "else" case, if you insert new data into the database with EF, you should expect to get the number of inserted data, but instead, you get 0, which means there is no row inserted.
• Error: Use for significant problems that prevent specific functionalities but do not cause the entire application to fail.
• Critical: Use for severe issues that require immediate attention and could cause the entire application or system to fail.

By default, built-in logging in ASP.NET Core has 3 providers (destination where the log message is printed): console, debug, and EventLog (Windows Only).

If we look at the console kestrel above, by default the minimum log level is set to Information. Hence the Trace and Debug level is not printed. You can change the behavior by changing the configuration in appsettings.json

We set the minimum log level into "trace" so it is successful to print log messages from traceand debug and above severity level events. But how to use logger in other than program files like in controller, service, repository, and other files? You can do it by injecting it into the method or constructor right away without needing to configure and register the logging service in the IoC Container beforehand.

You can ask the IoC container to inject ILoggerobject and you can store the injected logger object as a field and then use it anytime you want to create a log event. If you notice there is a message template with a placeholder (curly brace) in the log event to capture dynamic values as structured logging instead of embedding them directly into the log message as plain text. This offers benefit for easy to search and analysis logs (we will talk about it later)

HTTP Logging

It's important to log information about incoming HTTP requests and HTTP responses so you can identify the incoming request.

HTTP logging captures details about each incoming HTTP request and outgoing response. This includes information such as the request path, method (GET, POST, etc.), headers, and response status codes. This makes it easier to trace the flow of requests through your application and identify issues like incorrect routing or faulty response.

how to configure HTTP logging:

• you need to add HTTP logging service into the IoC container
• you need to use the built-in middleware of UseHttpLogging() to enable automatic logging of HTTP requests and responses in your application

By default, HTTPLogging doesn't log information about the request body and response body. You can set the configuration to capture request and response body but that is not recommended because if you log every incoming request body and response body it will overhead and slow down your server performance. Only log body if in an extremely needed situation.

Serilog

In this post, i will show you my favorite log framework, serilog. Why serilog is a good choice then built-in logging ASP.NET? Because they offer more sinks (sink in serilog refers to log destination). You can print the log event into a file, database (SQL Server, MySQL, etc), Seq, Azure, and have more powerful structured logging.

after that you can configure in program file

How to utilize serilog in ASP.NET Core

First, you need to install Serilog and Serilog.AspNetCore from nugget package. In this post, i will show you how to send a log event into 3 sinks which are console, file, and Seq. So you need to install the respective serilog sinks (Serilog.Sinks.Console, Serilog.Sinks.File, and Serilog.Sinks.Seq)

Seq

If you don't know Seq, Seq is a hosted monitoring tool for easy search and analysis in realtime for structured log. Here is the link to how to download and set seq tool on your machine https://docs.datalust.co/docs/getting-started

To set Serilog as logging provider add following code into Program file

above code tell serilog to read its configuration is loaded from configuration file such as appsetting.json and read services in IoC container and make available to serilog.

here how to set serilog configuration

Using section to determine which sinks to include, and then it uses those sinks for logging

Each sink has its configuration you can configure it in WriteTo section, for every sink need a Nameproperty. For Seq you need to Supply serverUrl which locates the URL of the Seq server in the Args section and for the file sink you need to supply a path to find where the file will be created for the first time and append the log message if the file already exists, in addition, you can add more configuration such as rollingInterval to determines how frequently new log file will be created based on the specified time interval, fileSizeLimitBytes to limit the maximum size of the log file and rollOnFileSizeLimit set to true to create a new file every time the size of log file reaches maximum limit.

console serilog looks like

file serilog looks like

seq serilog looks like

Here is one of the benefits use of a structured log instead of a static message log, You can search by property of log-structured event context like below

Enricher

An enricher is additional information or context like machine name, environment’s user name, and other custom user-defined information that will attach to your log event. It enriches information so it will help make it easier to debug and analyze. Enricher will add key-value pairs to your logs.

If you wanna add context that is true for all log events you can add static global key-value pairs by adding Properties to appsettings.json and adding key-value pair as nested property

You can add dynamic value into context with the help of the Diagnostic Context mechanism, there are 2 main types which are LogContext and IDiagnosticContext.
Note: for both dynamic contexts you need to supply LogContext as a value in the Enrichsection.

LogContext
Dynamically add properties to log events for a specific block code by executing LogContext.PushProperty() static method inside using statement. But first, you need to install Serilog.Enrichers.Context package from nugget package manager

context will be attached only for log event that inside using block of LogContext.PushProperty()

IDiagnosticContext
Dynamic context that only appears in the completion request response of the log event. But first, you need to configure Serilog’s request logging middleware which is app.UseSerilogRequestLogging().Unlike useHttpLogging which logs HTTP requests and responses in several events, serilog’s request logging only logs a single event at the completion of the HTTP request response.

First, you need to inject IDiagnosticContext instance then you can set the context to completion of the HTTP request-response with Set IDianosticContext instance's method.

Conclusion

Logging is vital for every application. Especially for big and complex applications. You can perform identity and analysis behavior of your application in production hence you can easily find the root of the problem if there is a bug or unintended behavior in your application easily and quickly, it is also used as a performance monitor because it logs the response time of request so if there is something that taking a long time you as a developer can optimize it, so it is recommended that you always use logging system each time you develop a new application

Comments

[Fadhil Ahsan]

Interesting🤟🏽