Opt-in to TraceId and SpanId enrichment for ASP.NET Core 5.0 logs

[cloudnin9]

Hello, Serilog community. Firstly, thank you for the great library!

Description
I am trying out Asp.Net on Net 5 Preview 7 so I have created 2 web API projects one targeting [netcoreapp3.1] and another targeting [net5]

The problem is when I am looking at logs, I no longer see TraceId and SpanId for the API targeting [net5] with the DotNet 5 preview 7 SDK.

I also tested using the vanilla Logger and there was no issue there. Do I have to configure something, did I just miss something or is the DotNet 5 Preview SDK not fully supported yet?

Thanks for any info.

Reproduction
Below is my bootstrapping code, it is identical for both APIs,

using System.Diagnostics;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Hosting;
using Serilog;
using Serilog.Formatting.Elasticsearch;

namespace WebApplication1
{
    public class Program
    {
        public static void Main(string[] args)
        {
            Activity.DefaultIdFormat = ActivityIdFormat.W3C;
            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Debug()
                .Enrich.FromLogContext()
                .WriteTo.Console(new ExceptionAsObjectJsonFormatter(renderMessage: true))
                .CreateLogger();
            CreateHostBuilder(args).Build().Run();
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
            .UseSerilog()
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });
    }
}

Expected behavior
Be able to see TraceId and SpanId in my logs, regardless of the AspDotnet runtime version

Relevant package, tooling and runtime versions

<Project Sdk="Microsoft.NET.Sdk.Web">

  <PropertyGroup>
    <TargetFramework>net5.0</TargetFramework>
    <UserSecretsId>b7a811b1-eb5a-4655-b19c-5e97c4ae1370</UserSecretsId>
    <DockerDefaultTargetOS>Linux</DockerDefaultTargetOS>
  </PropertyGroup>

  <ItemGroup>
    <PackageReference Include="Microsoft.VisualStudio.Azure.Containers.Tools.Targets" Version="1.10.9" />
    <PackageReference Include="Serilog.AspNetCore" Version="3.4.0" />
	  <PackageReference Include="Serilog.Formatting.Elasticsearch" Version="8.2.0" />
  </ItemGroup>

</Project>

Additional context

[nblumhardt]

Hi! Thanks for the note.

It looks like these just became opt-in in .NET 5, and baked into the logger factory itself, to reduce fixed logging overheads.

Serilog's ASP.NET Core/hosting integration will need a similar opt-in enricher, enabled via UseSerilog() - would be great if anyone following along has time to explore what is required, and spike up an impl.

ASP.NET Core impl PR: dotnet/aspnetcore#11211

[cloudnin9]

Thanks for the very informative reply @nblumhardt.
Should I keep this bug active?
This looks more like a new feature, due to the changes in dotnet.

[nblumhardt]

@naingyelin we'll need to track this, so this ticket is useful, thanks 👍

[techgeek03]

Hi!
I wrote a very simple enricher just to get the values out for now until we have a native solution in Serilog.

public class ActivityEnricher : ILogEventEnricher
    {
        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            var activity = Activity.Current;
            
            logEvent.AddPropertyIfAbsent(new LogEventProperty("SpanId", new ScalarValue(activity.GetSpanId())));
            logEvent.AddPropertyIfAbsent(new LogEventProperty("TraceId", new ScalarValue(activity.GetTraceId())));
            logEvent.AddPropertyIfAbsent(new LogEventProperty("ParentId", new ScalarValue(activity.GetParentId())));
        }
    }

    internal static class ActivityExtensions
    {
        public static string GetSpanId(this Activity activity)
        {
            return activity.IdFormat switch
            {
                ActivityIdFormat.Hierarchical => activity.Id,
                ActivityIdFormat.W3C => activity.SpanId.ToHexString(),
                _ => null,
            } ?? string.Empty;
        }

        public static string GetTraceId(this Activity activity)
        {
            return activity.IdFormat switch
            {
                ActivityIdFormat.Hierarchical => activity.RootId,
                ActivityIdFormat.W3C => activity.TraceId.ToHexString(),
                _ => null,
            } ?? string.Empty;
        }

        public static string GetParentId(this Activity activity)
        {
            return activity.IdFormat switch
            {
                ActivityIdFormat.Hierarchical => activity.ParentId,
                ActivityIdFormat.W3C => activity.ParentSpanId.ToHexString(),
                _ => null,
            } ?? string.Empty;
        }
    }

and then used it when configuring Serilog

public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureLogging(loggingBuilder =>
                {
                    loggingBuilder.Configure(options =>
                    {
                        options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId;
                    });
                })
                .UseSerilog((context, loggerConfiguration) =>
                    loggerConfiguration
                        .ReadFrom.Configuration(context.Configuration)
                        .Enrich.FromLogContext()
                        .Enrich.With<ActivityEnricher>()
                        .Enrich.WithExceptionDetails()
                        .WriteTo.Console(new RenderedCompactJsonFormatter()))
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });

However I wonder why Serilog does not get the values from the logging scope automatically. Is it because it is not using LoggerExternalScopeProvider ?

[davidfowl]

However I wonder why Serilog does not get the values from the logging scope automatically. Is it because it is not using LoggerExternalScopeProvider ?

That's correct.

[RehanSaeed]

Is anyone starting this? Otherwise I'll dump @techgeek03's code in a NuGet package called Serilog.Enrichers.Span.

[RehanSaeed]

I rustled up a new NuGet package for this purpose: https://github.com/RehanSaeed/Serilog.Enrichers.Span

[kennethlong]

Just an FYI @techgeek03's code changes work with 3.1 as well. I added a null check when assigning activity in the Enrich method to catch cases where Activity.Current wasn't set. Thanks for this, saved me hours of fiddling! :-)

[RehanSaeed]

Added that check in the 1.0.1 release.

RehanSaeed/Serilog.Enrichers.Span#1

[terryaney]

@RehanSaeed

ActivityTrackingOptions

Is setting this required? In your nuget package you don't show that step in the readme. Additionally, I can't get mine to compile:

public static IHostBuilder CreateHostBuilder( string[] args ) =>
	Host.CreateDefaultBuilder( args )
		.ConfigureLogging( loggingBuilder =>
		{
			loggingBuilder.Configure( options =>
			{
				options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId;
			} );
		} )
		.UseSerilog()
		.ConfigureWebHostDefaults( webBuilder =>
			{
				webBuilder.UseStartup<Startup>();
			} );

Error:

'ILoggingBuilder' does not contain a definition for 'Configure' and the best extension method overload 'WebHostBuilderExtensions.Configure(IWebHostBuilder, Action)' requires a receiver of type 'IWebHostBuilder'

[terryaney]

@RehanSaeed I was missing using Microsoft.Extensions.Logging;. However, after doing this, I have a .NET 5 Razor Pages site making a call to a .NET 5 Web API site I wrote, however, the TraceId and SpanId don't match on log entries from both. Should they or is more configuration required?

1. Should ParentId be set automatically? They always seem to be 00000000.
2. Should I even use CorrelationId or does that serve same purpose as TraceId/ParentId?

[RehanSaeed]

If both are .NET 5 (this means they default to W3C format of spans) and you use HttpClient to make the call to the API, then the parent ID should be set for you via HTTP headers (see Deep Dive into Open Telemetry for .NET for more details).

[terryaney]

Thanks. Read your article and have a question. But first, my issue was solved because that sample repo (and my code used same pattern) passed a DelegatingHandler into HttpClient constructor. The handler simply returned a json package if there was an error. If I don't pass that in, I now start to get SpanId/TraceId/ParentId.

My question is, how is ParentId set? For example, I have this flow.

Razor Page calls...

logger.LogInformation( "Calling DataLocker Web API" );
using ( var http = new HttpClient() ) // new StandardHttpMessageHandler( logger ) ) )
{
	var page = message.IsBad ? -1 : 1;	
	var response = await http.GetAsync( $"https://localhost:44330/calc-engines?page={page}" );
	var result = await response.Content.ReadAsStringAsync();
}

Log for 'Calling DataLocker Web API'

"RequestId": "80000097-0008-f600-b63f-84710c7967bb",
"SpanId": "c5182c40549ed547",
"TraceId": "42d94d07b98d1849a3b750fff71a32c4",
"ParentId": "0000000000000000"

A log event in the API

"RequestId": "800000d1-0004-fe00-b63f-84710c7967bb",
"SpanId": "48347b0869dfaf47",
"TraceId": "42d94d07b98d1849a3b750fff71a32c4",
"ParentId": "9f5a78712badf543"

So TraceId matches. I'm trying to understand what the definition of SpanId is. I'll read more. But my question is, how is ParentId determined? I would have thought 9f5a78712badf543 would have been 'somewhere' in the web site log identifying it as the parent?

[RehanSaeed]

When making a HTTP request, parent ID is passed via the traceparent HTTP header (See Crossing the Process Boundary) and then applied to the currently active span (or Activity object in .NET) in the ASP.NET Core framework itself.

[terryaney]

I understand that flow and had read Jimmy's article too, but it doesn't answer (or I missed it) where the ParentId is generated. It shows up as '9f5a78712badf543' above (or the 3rd segment of W3C pattern traceparent), and I'd expect that as the RequestId or SpanId from the original logging item, but from what I can tell, it is not.

Is my logging not outputting a property values that would have this id? I must be missing something, because as is, if I saw a log with a ParentId, it doesn't point back to anything meaningful, so it wouldn't be that helpful to me, I'd have to use timestamps and TraceId's?

[dwoldo]

@terryaney Had the same question. Digging a bit I found this issue over on dotnet runtime.

TL;DR; A new Activity in HttpClient is created before sending the HTTP request causing the ParentId to not match the SpanId of the prior activity. See dotnet/runtime#31862.

[Xitric]

@davidfowl Will this continue to be a problem in .NET 6 and onwards? (I assume so, but just wanted this confirmed).

@nblumhardt We use Serilog quite extensively in our products and wonder what is the best option for supporting trace contexts moving forward, so that we do not need to continue maintaining workarounds. Is the goal to actually support ISupportExternalScope in Serilog, and would that not entail changes in the core repository? Or, as hinted in #215, is the goal rather to build in an enricher or similar middleware that users can enable when configuring Serilog?

I ask because if we are to invest time into fixing this, we wish to ensure that we are headed in the right direction. For the meantime, we will continue using workarounds.

[Mario-Hofstaetter]

Ufff I just spent hours debugging why TraceId disappeared from our logs, till realizing we upgraded to .NET 6 meanwhile and then landing on this issue...

Thank you @RehanSaeed ❤️ for https://github.com/RehanSaeed/Serilog.Enrichers.Span

[dwoldo]

@terryaney I am afraid we've sunset the use-case for Serilog. Sorry I can't help further.

[nblumhardt]

I've been investigating a "long term" answer to this, which will work in ASP.NET and elsewhere; serilog/serilog#1955 is the first cut at it. Eyes, thoughts, comments most welcome over there :-)

[RehanSaeed]

Looks like Span support in Serilog has been merged which is awesome and means I can retire https://github.com/RehanSaeed/Serilog.Enrichers.Span.

[nblumhardt]

Hi everyone! As @RehanSaeed mentioned above, we've made some progress on this via the Serilog core package.

Before it will be useful though, support needs to be added to sinks - could anyone still watching this thread please drop a note in below with the names of the sinks most important to them in the context of this change? Thanks!

[terryaney]

Seq, Event Viewer, File. Well done.

[nblumhardt]

Thanks @terryaney 🙌

[lindeberg]

Great! What about ParentId?

[JinsPeter]

I would like these changes to apply to console, File and AWS cloud watch sinks. Thank you

…

On Wed, 4 Oct, 2023, 4:08 am Nicholas Blumhardt, ***@***.***> wrote: Hi everyone! As @RehanSaeed <https://github.com/RehanSaeed> mentioned above, we've made some progress on this via the Serilog core package. Before it will be useful though, support needs to be added to sinks - could anyone still watching this thread please drop a note in below with the names of the sinks most important to them in the context of this change? Thanks! — Reply to this email directly, view it on GitHub <#207 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADSMUJXDT4SB2WL6M7GYRGTX5SHVHAVCNFSM4PTT7VR2U5DIOJSWCZC7NNSXTN2JONZXKZKDN5WW2ZLOOQ5TCNZUGU4DGNBZGIZQ> . You are receiving this because you commented.Message ID: ***@***.***>

[nblumhardt]

Keeping a short log of instructions for sinks I've looked at.

Console

Updating Serilog to 3.1.0-* is enough for outputTemplate and JsonFormatter support.

outputTemplate

In the case of outputTemplate, the default doesn't include trace and span identifiers, so you need to configure Console with TraceId and SpanId placeholders:

    .WriteTo.Console(
        outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3} ({TraceId}:{SpanId})] {Message:lj}{NewLine}{Exception}")

if you want to see them.

BUT, the default output template formatting doesn't support conditional formatting, so when no trace or span is active the template above will include (:) in the output.

To improve on that, install Serilog.Expressions 4.0.0-* and use ExpressionTemplate with @tr and @sp:

    .WriteTo.Console(new ExpressionTemplate(
        "[{@t:HH:mm:ss} {@l:u3}{#if @tr is not null} ({@tr}:{@sp}){#end}] {@m}\n{@x}"))

JsonFormatter

Likewise, the built-in JsonFormatter has (to my eyes) awkward and verbose output. Install Serilog.Formatting.Compact version 2.0.0-* and use CompactJsonFormatter to improve on this, including @tr and @sp properties:

    .WriteTo.Console(new CompactJsonFormatter())

File

File configuration is exactly as above for Console; traces and spans are handled by formatters so you don't need to update the Serilog.Sinks.File package to any particular version.

OpenTelemetry

Install version 1.2.0-* of Serilog.Sinks.OpenTelemetry to consume the new trace and span properties directly from LogEvent (earlier versions of this package use a workaround to implement similar functionality).

Seq

Install version 6.0.0-* of Serilog.Sinks.Seq, this should pull in the dependencies required for trace and span ids to reach Seq in the corresponding fields.

[nblumhardt]

@lindeberg parent ids are properties of spans, while Serilog only produces log events at this point. Serilog events can be correlated with spans via the trace and span id properties, but to record spans themselves (start, end, trace id, span id, parent id, span name, attributes) you'll need to turn to another solution. Definitely still some interesting terrain to explore with Serilog in this space, though!

[lindeberg]

@nblumhardt Thanks for the explanation, that makes sense. Yeah, interesting to explore! Seems like a possible paradigm shift towards more traces (and trace events) and less logs as the tracing tools gets more accessible.

[lindeberg]

I've been investigating a "long term" answer to this, which will work in ASP.NET and elsewhere; serilog/serilog#1955 is the first cut at it. Eyes, thoughts, comments most welcome over there :-)

Elasticsearch is the important for sink for my organization atm so that's what I vote for. :D

[lindeberg]

Why isn't TraceId/SpanId logged here?

[nblumhardt]

Thanks for the feedback; contributions will be needed for Elasticsearch and AWS CloudWatch as I don't have either of these ready at hand (probably the case for a lot of sinks outside the few core ones in /serilog).

@lindeberg I think you need to add a direct dependency on Serilog.Extensions.Logging 7.0.0-dev-10353; I've updated that package now to 7.0.1-* to make this more obvious, a build should get to NuGet soon.

[lindeberg]

I created an issue for Serilog.Sinks.ElasticSearch: serilog-contrib/serilog-sinks-elasticsearch#573
And a discussion for Serilog.SInks.Grafana.Loki: serilog-contrib/serilog-sinks-grafana-loki#210

[lindeberg]

@nblumhardt I still can't get it to work

[nblumhardt]

@lindeberg I'll be able to dig in deeper later on, but what I think is happening here is the request logging middleware running right at the end of the pipeline, where the implicit activity has already been completed.

To check out this theory, you can try adding a regular Log.* call in one of your controllers.

[lindeberg]

@nblumhardt Also can't get it to work with call to Serilog static Logger, Serilog ILogger or Microsoft ILogger in neither Controller or Minimal API.

[nblumhardt]

@lindeberg debugging now. First issue, Serilog's RequestLoggingMiddleware constructs events manually and doesn't pick up trace and span ids - have a fix on the way for that. Second issue is ..... uncertain so far 😅 but I can reproduce what you're seeing 👍 (though in a larger app I have using these packages, everything flows through as expected 🤔).

[nblumhardt]

Okay, second issue is that outputTemplate doesn't recognize trace and span ids despite the tests suggesting otherwise.

Going back to investigate now, but in my working copy I see:

Using:

    .WriteTo.Console(new ExpressionTemplate(
        "[{@t:HH:mm:ss} {@l:u3}{#if @tr is not null} ({@tr}:{@sp}){#end}] {@m}\n{@x}"))

[nblumhardt]

Found the second issue - Serilog.Sinks.Console uses its own output template formatting in order to support themes.

[loekensgard]

Created an issue for Serilog.Sinks.Dynatrace iojancode/Serilog.Sinks.Dynatrace#13