LogContext does not flow to ILogger<T>

[opinionmachine]

I have a request and response-logging middleware defined in a shared library that I for political reasons wish to only depend on Microsoft's ILogger. I was hoping that Serilog.AspNetCore in the consuming API would take those request /response logs and populate them with my enriched LogContext, but they will not. It will flow global properties added in the log configuration in program.cs, such as assembly version and product name, but none of the things pushed in the LogContext in a preceding middleware will flow to the entries logged through ILogger.

Current behaviour: The log entries created via ILogger<T> lack the properties, while the ones created using the normal Serilog.Log.Logger do have pushproperties.

Expected behaviour: All PushProperty things in the pipeline should show up even if the blasphemer is using ILogger<T>.

(Just to clarify - logging elsewhere in the API, using Serilog directly, does have the enriched LogContext properties) I've attached an example that exhibits the behaviour I find undesireable: SerilogTormentor.zip

[kimbell]

Have you looked into the ILogger.BeginScope()? I use that in middleware to attach a set of values to every log statement inside the scope. I'm using Serilog and sending data to ELK without any problem.

public Task Invoke(HttpContext context, IHostingEnvironment hostingEnvironment)
{
        var dictionary = new Dictionary<string, object>
    {
         { "ApplicationName", hostingEnvironment.ApplicationName },
         { "EnvironmentName", hostingEnvironment.EnvironmentName },
         { "MachineName", Environment.MachineName}
    };

     // ensures all entries are tagged with some values
     using (_logger.BeginScope(dictionary))
     {
         // Call the next delegate/middleware in the pipeline
         return _next(context);
         }
}

[opinionmachine]

I haven't - I thought the LogContext would work. Is this the Serilog.ILogger, or the Microsoft ILogger<T>?

Is there any way to BeginScope for all ILoggers<T> ? Using ILoggerFactory or something? In that case my woes could be ended by simply doubling up on middlewares, one for the Serilog.LogContext and one for the ILogger<T> ...

[kimbell]

It's part of the new Microsoft logging infrastructure; it's implementation neutral. The idea is that scope information is passed on to each logging provider that has been registered. Then it's up to them to handle how they want to store the information. You can use Serilog today, and if something new and more wonderful shows up next year, it should be easier to switch it out.

At the point where you are logging, you shouldn't need to know how many or what type of logging provider has been configured.

[kimbell]

If you have a look the Logger implementation https://github.com/aspnet/Logging/blob/master/src/Microsoft.Extensions.Logging/Logger.cs#L41

It does a foreach (var loggerInfo in loggers) and calls Log().

[opinionmachine]

Yeah, I can add properties using a SerilogLoggerProvider.BeginScope in a middleware, but that is only heeded when Serilog.Log.Logger is used for logging. There doesn't seem to be a way to get ILogger<T> to care about contexts, regardless how I go about it (barring literally beginning scope inside the function that does the thing I'm about to log, which is unacceptable, as I might as well just add text to the log message, I'm not gaining anything by the context). According to Google, nobody else in the entire universe has done the basic logging middleware-with-properties example that is literally everywhere with Serilog.LogContext. Mind blown. The examples that show up are all adding context just before you are doing something inside the method, which if I'm honest is a bit tight, I have properties that are relevant across the entire call, I'd like to be able to set them in a request middleware like a normal person.

[kimbell]

I've created a small sample project that adds MachineName and CorrelationId to every log statement. SerilogTest.zip

 public Task InvokeAsync(HttpContext context)
        {
            var dictionary = new Dictionary<string, object>
            {
                { "CorrelationId", Guid.NewGuid().ToString("D") },
                { "MachineName", "Super Secret Server"}
            };

            // ensures all entries are tagged with some values
            using (_logger.BeginScope(dictionary))
            {
                // Call the next delegate/middleware in the pipeline
                return _next(context);
            }
        }

private readonly ILogger<ValuesController> _logger;

        public ValuesController(ILogger<ValuesController> logger)
        {
            _logger = logger;
        }

        // GET api/values
        [HttpGet]
        public ActionResult<IEnumerable<string>> Get()
        {
            _logger.LogInformation("Getting values");

            return new string[] { "value1", "value2" };
        }

When you look at the produced log file, you should find something similar to this:

{
    "Timestamp": "2018-07-24T17:46:06.9803297+02:00",
    "Level": "Information",
    "MessageTemplate": "Getting values",
    "Properties": {
        "SourceContext": "SerilogTest.Controllers.ValuesController",
        "ActionId": "38bf4c89-e0e6-432e-8efa-c6270446af0d",
        "ActionName": "SerilogTest.Controllers.ValuesController.Get (SerilogTest)",
        "CorrelationId": "3c9ae074-2ee2-47f1-b283-670eb054e27f",
        "MachineName": "Super Secret Server",
        "RequestId": "0HLFHFI7V6OTR:00000008",
        "RequestPath": "/api/values",
        "ConnectionId": "0HLFHFI7V6OTR"
    }
}

This will only add information to code running through the middleware pipeline. If you have code that runs in background tasks, i.e. IHostedService, you need a different approach.

 public static void Main(string[] args)
        {
            CreateWebHostBuilder(args)
                .UseSerilog((context, configureLogger) =>
                {
                    configureLogger
                        .ReadFrom.Configuration(context.Configuration)
                        // set these globally so that they work for all tasks (including background)
                        .Enrich.WithProperty("EnvironmentName", context.HostingEnvironment.EnvironmentName)
                        .Enrich.WithProperty("ApplicationName", context.HostingEnvironment.ApplicationName)
                        .Enrich.WithProperty("HostName", Environment.MachineName)
                        .WriteTo.Console();
                })
                .Build()
                .Run();
        }

[opinionmachine]

YES it was that simple. Just using a ILogger<MyMiddleware> makes it work further down in the pipeline!

Thank you very much for explaining this to me. I have to say it took a mental leap for me to understand that something i set on an ILogger<T> will work on an ILogger<K> but as long as I get my correlation IDs I'm happy!

[kimbell]

The T provided to the ILogger is only used to determine the name of the category used when logging. This can again be used to set different logging levels for different categories. I.e. you could set Microsoft's categories to Warning, and your code to Information.

[Neutrino-Sunset]

There is a problem with that approach, which is that attempting to write a log entry using the Serilog format for deconstructing an object does not work.

      public ValuesController(ILogger<ValuesController> logger)
      {
         _logger = logger;
      }

      [HttpGet]
      public ActionResult<IEnumerable<string>> Get([FromServices]IHostingEnvironment env)
      {
         // This fails.
         _logger.LogInformation("Hosting environment: {@env}", env);

         return new string[] { "value1", "value2" };
      }

Here the line that outputs env will be written to console and file ok, but if send to ElasticSearch using serilog-sinks-elasticsearch this entry will be completely missing, but there is no error in the log to indicate why.

I assume that since this is an ASP ILogger and not a Serilog ILogger the ILogger.LogInformation call is choking on the syntax of the {@env} somewhere. It's not obvious to me how to work around this though.

Anyone got any ideas?

[andymac4182]

@Neutrino-Sunset This sounds separate to this issue. If you could start a new issue with a copy of how you are setting up the sinks that would be great.

[Neutrino-Sunset]

I think the problem was that over the course of various testing I'd used the same message template deconstructed parameter name for arguments of type object and scalars, and when that occurs Elasticsearch cannot index the log event, so it doesn't appear.

It's a bit of a nasty issue that there doesn't seem to be any clear way of dealing with.

[andymac4182]

Ahh we had a similar issue when trialing the use of Elasticsearch with Serilog. We ended up staying with Seq for our log server as it handles this perfectly.

[btbensoft]

Here the line that outputs env will be written to console and file ok, but if send to ElasticSearch using serilog-sinks-elasticsearch this entry will be completely missing, but there is no error in the log to indicate why.

@Neutrino-Sunset how did you solve this problem?

Can i log any object as params? _logger.LogInformation("Hosting environment: {@env}", env);

thanks