Microsoft.AspNetCore.Hosting.Internal.WebHost and log4net.LogicalThreadContext.Properties["requestid"]

Question

I use netcore2.0 and I'm setting log4net.LogicalThreadContext property "requestid" with each request in my middleware class for logging purposes.

log4net.LogicalThreadContext.Properties["requestid"] = Guid.NewGuid().ToString("N");

But "Microsoft.AspNetCore.Hosting.Internal.WebHost" class does not show this property when logging rows.

I do not know how to set log4net.LogicalThreadContext.Propery["requestid"] for "Microsoft.AspNetCore.Hosting.Internal.WebHost".

I wish to tie all request logs from the beginning to the end. Does anyone have any insights which might help?

Regards!

UPDATE: Here is the code

using Microsoft.Extensions.Logging;
...

public static ILoggerProvider Log4NetProvider;

public static void Main(string[] args)
    {

#if DEBUG
        Log4NetProvider = new Log4NetProvider("log4net.Debug.config", ((o, 
exception) => exception.Message));
#else
        Log4NetProvider = new Log4NetProvider("log4net.Release.config", ((o, 
exception) => exception.Message));
#endif
        var host = new WebHostBuilder()
            .UseKestrel()
            .UseContentRoot(Directory.GetCurrentDirectory())                
            .ConfigureLogging((hostingContext, logging) =>
            {
                logging.AddProvider(Log4NetProvider);                   
            })
            .ConfigureServices(services =>
            {
                services.AddAutofac();
            })
            .UseIISIntegration()
            .UseStartup<Startup>()
            .Build();
        host.Run();

In Startup.cs Configure(IApplicationBuilder app, IHostingEnvironment env) i've set up as the very first thing.

app.UseMiddleware<Log4NetRequestIdMiddleware>();

public class Log4NetRequestIdMiddleware
{
    private readonly RequestDelegate _next;

    public Log4NetRequestIdMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public async Task Invoke(HttpContext context)
    {
        log4net.LogicalThreadContext.Properties["requestid"] = Guid.NewGuid().ToString("N");
        await _next(context);
    }
}

Log4net config file>

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
  <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
    <file value="C:\log\applog.log" />
    <rollingStyle value="Size"/>
    <maxSizeRollBackups value="500"/>
    <maximumFileSize value="5MB"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%utcdate|%-5level|%logger|%property{requestid}| %message %exception%newline" />
    </layout>
  </appender>
  <root>
    <level value="ALL" />
    <appender-ref ref="RollingFile" />
  </root>
</log4net>

Additional example from Fileappender.log (bold marking the RequestId)

2018-04-10 14:02:28,664|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|(null)| Request starting HTTP/1.1 GET http://localhost...
2018-04-10 14:02:28,956|INFO| Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|cfb2709e3b4f40559c365ecbb08a7746| Executing action method Controllers.HealtCheckStatusController.GetHealthCheckStatus 2018-04-10 14:02:29,486|INFO| Microsoft.AspNetCore.Mvc.Internal.ObjectResultExecutor|cfb2709e3b4f40559c365ecbb08a7746| Executing ObjectResult, writing value Microsoft.AspNetCore.Mvc.ControllerContext.
2018-04-10 14:02:29,510|INFO| Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|cfb2709e3b4f40559c365ecbb08a7746| Executed action Controllers.HealtCheckStatusController.GetHealthCheckStatus in 564.464ms
2018-04-10 14:02:29,520|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|(null)| Request finished in 858.9575ms 200 application/json; charset=utf-8

Answer 1

Why WebHost logger does not show the property

WebHost logger logs two messages - Request starting message and Request finished message.

Request starting message doesn't see requestid property because WebHost runs and logs the message before the first middleware included into pipeline in Startup class where requestid property is set.

Request finished message doesn't see requestid property because (I guess) WebHost logger is out of log4net.LogicalThreadContext. It is like Log4NetRequestIdMiddleware logger would not see requestid property if it would be set in controller action.

Possible solution

Since WebHost logger logs messages somewhere deep in HostingApplicationDiagnostics class from Microsoft.AspNetCore.Hosting.Internal namespace there is no any clear extension points to inject the code that would set requestid property. So, I think you can just log info in your middleware like it does WebHost logger:

public async Task Invoke(HttpContext context)
{
    var logger = httpContext.RequestServices.GetRequiredService<ILogger<Log4NetRequestIdMiddleware>>();
    log4net.LogicalThreadContext.Properties["requestid"] = Guid.NewGuid().ToString("N");
    
    var request = context.Request;
    string logMsg = string.Format(
            CultureInfo.InvariantCulture,
            "Request starting {0} {1} {2}://{3}{4}{5}{6} {7} {8}",
            request.Protocol,
            request.Method,
            request.Scheme,
            request.Host.Value,
            request.PathBase.Value,
            request.Path.Value,
            request.QueryString.Value,
            request.ContentType,
            request.ContentLength);
    
    logger.LogDebug(logMsg);

    await _next(context);
}