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: https://github.com/dotnet/aspnetcore/pull/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.

https://github.com/RehanSaeed/Serilog.Enrichers.Span/pull/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<IApplicationBuilder>)' 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 https://github.com/dotnet/runtime/issues/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

[JinsPeter]

@techgeek03 , @RehanSaeed

Looking at the enricher code here, or @RehanSaeed Serilog.Enrichers.Span library, I noticed that the enrichers prints different values for Span and TraceID using Hierarchical and W3C Activity ID Format.

     activity.IdFormat switch
            {
                ActivityIdFormat.Hierarchical => activity.Id,
                ActivityIdFormat.W3C => activity.SpanId.ToHexString(),
                _ => null,
            } ?? string.Empty;
            
     activity.IdFormat switch
            {
                ActivityIdFormat.Hierarchical => activity.RootId,
                ActivityIdFormat.W3C => activity.TraceId.ToHexString(),
                _ => null,
            } ?? string.Empty;

I thought activity.RootID helped filter all logs from different spans of the original activity and activity.Id traces the activity from the first span. What is different in W3C format? Isn't it just using a Guid? What am I missing?

[RehanSaeed]

W3C is the Open Telemetry industry standard format, while the other one is some proprietary Microsoft format that almost nobody should use.

[JinsPeter]

@RehanSaeed That part I understand. I am asking why the different fields?

[TimmyGilissen]

it was not that difficult to include the traceid and spandid.

just create the following class

`public class OpenTelemetryLogEnricher : ILogEventEnricher { public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { if (Activity.Current == null) return;

    logEvent.AddPropertyIfAbsent(new LogEventProperty("TraceId",
        new ScalarValue(Activity.Current.TraceId.ToString())));
    logEvent.AddPropertyIfAbsent(
        new LogEventProperty("SpanId", new ScalarValue(Activity.Current.SpanId.ToString())));
}

}`

then in your logging configuration.

config.Enrich.With<OpenTelemetryLogEnricher>();

[lucasoares]

it was not that difficult to include the traceid and spandid.

just create the following class

`public class OpenTelemetryLogEnricher : ILogEventEnricher { public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { if (Activity.Current == null) return;

    logEvent.AddPropertyIfAbsent(new LogEventProperty("TraceId",
        new ScalarValue(Activity.Current.TraceId.ToString())));
    logEvent.AddPropertyIfAbsent(
        new LogEventProperty("SpanId", new ScalarValue(Activity.Current.SpanId.ToString())));
}

}`

then in your logging configuration.

config.Enrich.With<OpenTelemetryLogEnricher>();

Hello.. Newbie in Serilog here, sorry for asking but I need to..

Will this enricher execute in the same thread where the log was made to get the correct and active Activity?

Thanks.

[JinsPeter]

Why don't you give it a minimalist trial?

On Tue, 7 Mar, 2023, 3:36 am Lucas Soares, @.***> wrote:

it was not that difficult to include the traceid and spandid.

just create the following class

`public class OpenTelemetryLogEnricher : ILogEventEnricher { public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) { if (Activity.Current == null) return;

logEvent.AddPropertyIfAbsent(new LogEventProperty("TraceId",
    new ScalarValue(Activity.Current.TraceId.ToString())));
logEvent.AddPropertyIfAbsent(
    new LogEventProperty("SpanId", new ScalarValue(Activity.Current.SpanId.ToString())));

}

}`

then in your logging configuration.

config.Enrich.With<OpenTelemetryLogEnricher>();

Hello.. Newbie in Serilog here, sorry for asking but I need to..

Will this enricher execute in the same thread where the log was made so it gets the correct and active Activity?

Thanks.

— Reply to this email directly, view it on GitHub https://github.com/serilog/serilog-aspnetcore/issues/207#issuecomment-1457080591, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADSMUJVULNXS3JVPF4ELW7DW2ZNXHANCNFSM4PTT7VRQ . You are receiving this because you commented.Message ID: @.***>

[sungam3r]

Will this enricher execute in the same thread where the log was made to get the correct and active Activity?

Yes.

[terryaney]

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.

@dwoldo So after a couple years, this dead project I was on was resurrected and I was again trying to figure out how ParentId, RequestId, SpanId, TraceId all relate. After (re-)implementing Serilog in the project, I ended up where I was before. TraceId matches in logging from 'site' and logging from 'api' (that the site called), but nothing else seems to relate. Did you copy the 'hack' mentioned in that issue above to try and get things to work? Or just leave it as is? I haven't tried the hack based on some comments in the issue stating it had potential problems, and I don't know enough (yet) about W3C activity id format to completely understand some of the later comments in the thread.

[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; https://github.com/serilog/serilog/pull/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!