'Serilog UseSerilogRequestLogging logging after request, not before

I followed this article https://github.com/serilog/serilog-aspnetcore to set up the diagnostic message logged onto file by Serilog with.NET Core v5

My Configure method is as shown:

public static void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
    if (env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }

    app.UseSerilogRequestLogging(); //-> added this line as per docs

    app.UseRouting();
    app.UseCors(MyAllowSpecificOrigins);

    /********** Authentication settings **********/
    // Don't move this code from here.
    app.UseAuthentication();
    app.UseAuthorization();
    /********** Authentication settings **********/

    app.UseEndpoints(endpoints =>
    {
        endpoints.MapControllers();
    });
}

I am using ILogger interface to log in all the layers of my web application. However; when i execute, the diagnostic logs from RequestLoggingMiddleware does not appear in order of execution as shown in below log sample:

2022-02-28 20:40:07.938 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:07.979 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 1896.5003 ms
2022-02-28 20:40:08.089 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:08.106 +05:30 [INF] MyApplication..API.Services.Interface.IIdentityServiceWrapper=  Profile Details fetched from Memory Cache 
2022-02-28 20:40:08.111 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 52.7317 ms
2022-02-28 20:40:08.150 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:08.154 +05:30 [INF] MyApplication..API.Services.Interface.IIdentityServiceWrapper=  Profile Details fetched from Memory Cache 
2022-02-28 20:40:08.155 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 27.4997 ms
2022-02-28 20:40:08.187 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:08.201 +05:30 [INF] MyApplication..API.Services.Interface.IIdentityServiceWrapper=  Profile Details fetched from Memory Cache 
2022-02-28 20:40:08.202 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 40.3553 ms
2022-02-28 20:40:09.156 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 403 in 2.6942 ms
2022-02-28 20:40:09.631 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 403 in 0.5469 ms
2022-02-28 20:40:09.659 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:09.662 +05:30 [INF] MyApplication..API.Services.Interface.IIdentityServiceWrapper=  Profile Details fetched from Memory Cache 
2022-02-28 20:40:09.662 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 25.4166 ms
2022-02-28 20:40:10.190 +05:30 [INF] MyApplication..API.Services.Interface.SomeService=  ******Method: GetDownloadDetails Started*******
2022-02-28 20:40:10.193 +05:30 [INF] MyApplication..API.Services.Interface.IIdentityServiceWrapper=  Profile Details fetched from Memory Cache 
2022-02-28 20:40:10.194 +05:30 [INF] Serilog.AspNetCore.RequestLoggingMiddleware=  HTTP GET /api/Download responded 200 in 23.2961 ms

My Actual serial method looks something like this:

 private readonly ILogger<IService> logger;
 public List<Details> GetDownloadDetails(List<string> TransactionIdList = null, string limit = null)
 {
     logger.LogInformation("******Method: GetDownloadDetails Started*******");
 }

Hence, how do i make it to appear in order so that i can track when a thread enters and exists (assuming one 1 request at a time).

c++sharpasp.net-core.net-coreasp.net-core-webapiserilog


Solution 1:[1]

The message

HTTP GET /api/Download responded 200 in 1896.5003 ms

intentionally includes the time taken. That is obviously not known until it is complete. The benefit is that there is one message.

Hence, if you want a starting message, and to know the time taken, you'll have to take matters into your own hands, i.e.

  • don't request that logging
  • do something similar, but do it before the request

(IMO you should just live with it as it is though)

Sources

This article follows the attribution requirements of Stack Overflow and is licensed under CC BY-SA 3.0.

Source: Stack Overflow

Solution Source
Solution 1 Ruben Bartelink

Related Questions