Post
Ask Question

Request Tracing And Logging Between Multiple MicroService With Correlation Id Using Serilog In .NET Core

Introduction

 
When we develop an application, logging is an important factor to troubleshoot any application problem. We can write logs in either text file or console or cloud with different techniques, as you aware.
 
For example - NLog, Log4NET, Serilog, ELMAH etc...
 
In micro service based applications, tracing a failed request or request analysis would be bit complicated. Because each service (Micro service) is running in an isolated way and the problem is that we might be unaware of request sequence or chain of individual requests (where the request got failed). To handle this situation, we generate and pass Correlation Id in each request header using .Net Core Middleware so that we can log information along with Correlation Id. Due to this process we can easly trace the logs and find the solution.
 
To achieve this, we are using Serilog Logging framework. Serilog is a newer logging framework for .NET. It was built with structured logging in mind. It makes it easy to record custom object properties and even output your logs to JSON.
 
Prerequisites
 
To know more about Serilog please visit the following link. 
 
https://serilog.net/ 
 
Refer to the following diagram,
 
Request Tracing And Logging Between Multiple MicroService With Correlation Id Using Serilog In .NET Core
 
Step 1
 
From the above diagram, the user makes a request which goes to Service 1,  and Service 1 calls to Service 2, and Service 2 calls to Service 3. So internally the request passes to different services to get the response to the end user, and at the same time logs are also logged in text file (In my case). So each service has their own log files.
 
Step 2 
 
So think about the situation, if any of the services goes down or fails to respond. What happens is that the end response is an appropriate error code that would be returned. In this case we look into the log file and analyze the initial request to end response.
 
But there would be multiple microservices running and it would have their own logs in their place. So how can the developer find the issue of the particular request?
If multiple requests come at the same time and a few of them fail for some reason, tracing the logs would be difficult because all the request logs are logged in the same text file. 
 
Step 3
 
To overcome this situation, we need some identification for each request wherever it is passing, which means whatever micro services are invoked by that particular request. To do that we are using Serilog for structured logging with Correlation Id. So whenever we log an information we need to append the correlationId also.
 
Step 4 
 
Let's demonstrate it in action by creating two micro services named "Source Application" and "Target Application" using .Net Core. In Source Application and Target Application we used Microsoft.Extensions.Logging for logging. So when we invoke from Source to Target application we need to pass CorrelationId in header of that request. To do that we can create Middleware to add correlationid in http request context. 
 
Step 5 
 
Source Application Middleware looks like the below LogHeaderMiddleware.cs which will invoke for each request and add CorrelationId in that http request context.
  1. namespace Source_Application.Middleware  
  2. {  
  3.     public class LogHeaderMiddleware  
  4.     {  
  5.         private readonly RequestDelegate _next;  
  6.   
  7.         public LogHeaderMiddleware(RequestDelegate next)  
  8.         {  
  9.             this._next = next;  
  10.         }  
  11.   
  12.         public async Task InvokeAsync(HttpContext context)  
  13.         {  
  14.             var header = context.Request.Headers["CorrelationId"];  
  15.             string sessionId;  
  16.   
  17.             if (header.Count > 0)  
  18.             {  
  19.                 sessionId = header[0];  
  20.             }  
  21.             else  
  22.             {  
  23.                 sessionId = Guid.NewGuid().ToString();  
  24.             }  
  25.   
  26.             context.Items["CorrelationId"] = sessionId;  
  27.             await this._next(context);  
  28.         }  
  29.     }  
  30. }  
Step 6
 
We need to configure "LogHeaderMiddleware" middleware in Startup.cs.
  1. public void Configure(IApplicationBuilder app, IHostingEnvironment env)  
  2.       {  
  3.           app.UseMiddleware<LogHeaderMiddleware>();  
  4.           if (env.IsDevelopment())  
  5.           {  
  6.               app.UseDeveloperExceptionPage();  
  7.           }  
  8.   
  9.           app.UseMvc();  
  10.       }  
Step 7
 
Next we need to make a request from Source application into Target application. For example like below. 
  1. var response = await _httpClient.GetAsync("api/values/sample");  
Step 8
 
Using middleware, correlationid has been added into that request context. Now we have to take the correlationId from that request context and add it into request header. To do this we need to override sendAsync action (RequestHandler.cs) like below. 
  1. namespace Source_Application.Service  
  2. {  
  3.     public class RequestHandler : DelegatingHandler  
  4.     {  
  5.         private readonly ICorrelationIdAccessor _correlationIdAccessor;  
  6.         private readonly IHttpContextAccessor _httpContextAccessor;  
  7.   
  8.         public RequestHandler(ICorrelationIdAccessor correlationIdAccessor, IHttpContextAccessor httpContextAccessor)  
  9.         {  
  10.             this._correlationIdAccessor = correlationIdAccessor;  
  11.             this._httpContextAccessor = httpContextAccessor;  
  12.         }  
  13.   
  14.         protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)  
  15.         {    
  16.             request.Headers.Add("CorrelationId", _correlationIdAccessor.GetCorrelationId()); // Getting correlationid from request context. 
  17.             return base.SendAsync(request, cancellationToken);  
  18.         }  
  19.     }  
  20. }  
Step 9
 
In Startup.cs file, wehave to make the following configuration.
  1. public void ConfigureServices(IServiceCollection services)  
  2.       {  
  3.           services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_2);  
  4.           services.AddTransient<RequestHandler>();  
  5.           services.AddHttpClient<TargetClient>((client) => client.BaseAddress = new System.Uri("http://localhost:59218"))  
  6.               .AddHttpMessageHandler<RequestHandler>(); //Override SendAsync method 
  7.   
  8.           services.AddHttpContextAccessor();  //For http request context accessing
  9.           services.AddTransient<ICorrelationIdAccessor, CorrelationIdAccessor>();  //DI
  10.       }  
Step 10
 
That's it from Source Application side, now let's move on to Target application. In Target application we have controller action to accept incoming request. In this application we need to log with CorrelationId which comes from Source. To do that we need to implement Middleware (LogHeaderMiddleware.cs) to pick up the correlationid from request header and append in logger scope when request comes from any service (In our demo --> Source application) so that correlationId can be logged in log file whereever the request scope travels.
  1. namespace Target_Application.Middleware  
  2. {  
  3.     public class LogHeaderMiddleware  
  4.     {  
  5.         private readonly RequestDelegate _next;  
  6.   
  7.         public LogHeaderMiddleware(RequestDelegate next)  
  8.         {  
  9.             this._next = next;  
  10.         }  
  11.   
  12.         public async Task InvokeAsync(HttpContext context)  
  13.         {  
  14.             var header = context.Request.Headers["CorrelationId"];  
  15.             if (header.Count > 0)  
  16.             {  
  17.                 var logger = context.RequestServices.GetRequiredService<ILogger<LogHeaderMiddleware>>();  
  18.                 using (logger.BeginScope("{@CorrelationId}", header[0]))  
  19.                 {  
  20.                     await this._next(context);  
  21.                 }  
  22.             }  
  23.             else  
  24.             {  
  25.                 await this._next(context);  
  26.             }  
  27.         }  
  28.     }  
  29. }  
Step 11
 
So we successfully retrieved CorrelationId from the incoming request. Now we need to log in text file, to do that we have to install Serilog.AspNetCore package from Nuget. Once it's  installed successfully we can implement Serilog configuration as below in Startup.cs. 
  1. public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>  
  2.           WebHost.CreateDefaultBuilder(args)  
  3.             .UseSerilog((context, config) =>  
  4.             {  
  5.                 config.WriteTo.Debug(new JsonFormatter(renderMessage: true), LogEventLevel.Verbose);  
  6.                 config.MinimumLevel.Information();  
  7.             })  
  8. .UseStartup<Startup>();  
Step 12
 
As with Source application we have to configure Middleware in Startup.cs file also.
  1. public void ConfigureServices(IServiceCollection services)  
  2.       {  
  3.           services.AddMvc().SetCompatibilityVersion(CompatibilityVersion.Version_2_2);  
  4.           services.AddHttpContextAccessor();  
  5.       }  
  6.   
  7.       // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.  
  8.       public void Configure(IApplicationBuilder app, IHostingEnvironment env)  
  9.       {  
  10.           app.UseMiddleware<LogHeaderMiddleware>();  
  11.   
  12.           if (env.IsDevelopment())  
  13.           {  
  14.               app.UseDeveloperExceptionPage();  
  15.           }  
  16.   
  17.           app.UseMvc();  
  18.       }  
Step 13
 
As I stated earlier, Serilog is a structured logging. So the final step is configuring correlationId logging format as like below.
  1. public Startup(IConfiguration configuration)  
  2.         {  
  3.             Configuration = configuration;  
  4.             Log.Logger = new LoggerConfiguration()  
  5.   
  6.             .WriteTo.File("test.txt",  
  7.                    outputTemplate: "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} [{Level:u3}] {CorrelationId} {Message:lj}{NewLine}{Exception}")  
  8.                .CreateLogger();  
  9.         }  
"test.txt" --> File will be created in root folder of this application and written in "outputtemplate" format. For example refer to the following.
  1. 2020-03-04 15:23:38.140 +05:30 [INF] 80000018-0005-fb00-b63f-84710c7967bb Request starting HTTP/1.1 GET http://localhost:59218/api/values/sample    
  2. 2020-03-04 15:23:38.140 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executing endpoint 'Target_Application.Controllers.ValuesController.Get (Target Application)'  
  3. 2020-03-04 15:23:38.140 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Route matched with {action = "Get", controller = "Values"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.ActionResult Get() on controller Target_Application.Controllers.ValuesController (Target Application).  
  4. 2020-03-04 15:23:38.140 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executing action method Target_Application.Controllers.ValuesController.Get (Target Application) - Validation state: "Valid"  
  5. 2020-03-04 15:23:38.964 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Target method invoked  
  6. 2020-03-04 15:23:38.964 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executed action method Target_Application.Controllers.ValuesController.Get (Target Application), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 823.5  
  7. 2020-03-04 15:23:38.964 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executing ObjectResult, writing value of type 'Microsoft.AspNetCore.HttpSys.Internal.RequestHeaders'.  
  8. 2020-03-04 15:23:38.965 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executed action Target_Application.Controllers.ValuesController.Get (Target Application) in 824.3061ms  
  9. 2020-03-04 15:23:38.965 +05:30 [INF] d73d329d-ffd1-4d2b-bdff-91291c20327a Executed endpoint 'Target_Application.Controllers.ValuesController.Get (Target Application)'  
  10. 2020-03-04 15:23:38.965 +05:30 [INF] 80000018-0005-fb00-b63f-84710c7967bb Request finished in 825.0772ms 200 application/json; charset=utf-8  
Note
I've attached "Source Application" and "Target Application" with this article. If you want more explanation or a live example please download the projects and refer to that.
 
I hope this was helpful for you. Enjoy ;)


Similar Articles