Properties set via middleware don't show up in exception logs

[BrianVallelunga]

I'm trying to log the tenant of my multi-tenant application by having a Tenant property added to all logs. To accomplish this, I have middleware that adds the property to the LogContext:

public class TenantContextLoggingMiddleware
{
    private readonly RequestDelegate next;

    public TenantContextLoggingMiddleware(RequestDelegate next)
    {
        this.next = next;
    }

    public async Task Invoke(HttpContext context, ITenantResolver tenantResolver)
    {
        var tenant = await tenantResolver.ResolveAsync();

        // Add tenant to logging context
        using (LogContext.PushProperty("Tenant", tenant.Name))
        {
            await this.next.Invoke(context);
        }
    }
}

This is configured in my Startup.cs file as:

public void Configure(IApplicationBuilder app)
{
    // ...
    app.UseMiddleware<TenantContextLoggingMiddleware>();
    // ...
    app.UseMvc();
}

I've tested that the middleware is invoked correctly, but unfortunately, the "Tenant" value is never included in my logs. Logs include properties set when I created by logger, such as:

// BuildNumber will always work
Log.Logger = new LoggerConfiguration()
                 .Enrich.WithProperty("BuildNumber", BuildNumberUtility.GetBuildNumber())

What am I missing here? Thanks.

For reference, I'm using the latest Serilog.AspNetCore (2.1.1) and running Serilog 2.6.0 on ASP.NET Core 2.0.6.

[nblumhardt]

Hi Brian - my guess is that you're missing Enrich.FromLogContext() in your logger configuration - does this do the trick? NB

[BrianVallelunga]

I don't think that's it. Here's my full configuration:

        Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Information()
            .MinimumLevel.Override("System", LogEventLevel.Warning)
            .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
            .Enrich.FromLogContext()
            .Enrich.WithProperty("BuildNumber", BuildNumberUtility.GetBuildNumber())
            .Enrich.WithProperty("AzureHost", Environment.GetEnvironmentVariable("WEBSITE_HOSTNAME"))
            .WriteTo.Console()
            .WriteTo.Stackify()
            .CreateLogger();

[nblumhardt]

Thanks for the follow-up. Sounds like it'll need some good-ol'-fashioned debugging - all looks right to me. Checking out Serilog's SelfLog may be worthwhile.

[BrianVallelunga]

Good to know my configuration is fine. I'll dig into this and see what I can find.

[sbobkin]

@BrianVallelunga don't know if you've resolved this already, but does your middleware rely on having the user authenticated or anything similar in the pipeline to get the information it needs? If yes, the order of the app.Use* statements will matter ie: the UseMiddlewarewill have to come after whatever other middleware may set the appropriate information.

[BrianVallelunga]

I have not fully resolved this, no. I don't think it is an ordering issue, as the data I'm attaching is sometimes in middleware, but also often in services. I suspect it is related to nested contexts and possibly async interaction. I will try to check the ordering though when I get back around to this. Thanks for the suggestion.

[BrianVallelunga]

EDIT: SORRY! My sample didn't include .Enrich.FromLogContext(), which I do have in my ASP.NET Core site. I'll continue to work on the issue and try to reproduce in that environment.

I was able to create a reproducible sample. The code is simple enough, so that probably means I'm using the logging contexts improperly. The entire console app is below. I would expect it to have both the tenant and the service name in the output statement, but the tenant name is missing. Here's the code:

using Serilog;
using Serilog.Context;
using System;

namespace LogContextTest
{
    class Program
    {
        static void Main(string[] args)
        {
            var logger = new LoggerConfiguration()
                                .MinimumLevel.Information()
                                .WriteTo.Console()
                                .CreateLogger();

            var service = new TestService(logger);

            using (LogContext.PushProperty("Tenant", "Test Tenant"))
            {
                service.DoSomething();
            }

            Console.ReadLine();
        }
    }

    class TestService
    {
        private ILogger logger;

        public TestService(ILogger logger)
        {
            this.logger = logger.ForContext("ServiceName", "Test Service");
        }

        public void DoSomething()
        {
            this.logger.Information("Doing something for {Tenant} in {ServiceName}");
        }
    }
}

I would expect the output to be Doing something for Test Tenant in Test Service, but only see Doing something for {Tenant} in Test Service

Obviously this isn't ASP.NET Core related it turns out. Should I move this issue to the main Serilog repo?

[nblumhardt]

Hi @BrianVallelunga - the issue here, I think is that in:

this.logger.Information("Doing something for {Tenant} in {ServiceName}"

you're not passing Tenant or ServiceName directly into that logging statement. The message templates passed to the various log methods - Information(), Warning() etc., can only name parameters passed to the same call - not pick up data from the log context/enrichers/elsewhere.

https://github.com/Suchiman/SerilogAnalyzer will catch these for you.

HTH! Nick

[krajek]

@BrianVallelunga is your problem fixed? Can we close the issue?

[BrianVallelunga]

I'll verify and report back.

[BrianVallelunga]

I think we can close this. I'm unsure if this is still an issue, but it seems better in my situation. I'm mostly interested in the values being appended as additional data when logged, not necessarily for use as values in the log message itself. If I can ever recreate this simply, I'll open a new ticket with a sample project.

[fairmutex]

For anyone here for a similar issue check if this helps https://github.com/fairmutex/serilog-azure-claims-sample