Collect and propagate current trace and span ids through LogEvent

[nblumhardt]

Fixes #1923
Fixes serilog/serilog-aspnetcore#207

Note that trace and span ids will only be collected when at least one activity listener is present - this will be the case in just about all practical implementation scenarios right now, I think, but is still worth bearing in mind.

The addition of {TraceId} and {SpanId} to MessageTemplateTextFormatter is technically a breaking change; existing user templates with top level trace and span properties will now pull in the values from LogEvent rather than identically-named properties. In most cases these will have the same value/representation, so I don't think it justifies a major version bump, though it'd need a prominent call-out in the release notes.

The immediate benefit from merging this PR will be the removal of the ConditionalWeakTable workaround in Serilog.Sinks.OpenTelemetry, and should hopefully pave the way for better integration with the OpenTelemetry SDK, if/when that happens.

Further down the line, most sinks for APMs/log servers/services will be able to pull in these properties for correlation purposes.

Final note, this adds a dependency on System.Diagnostics.DiagnosticSource on older platforms; this is no different from how we support ValueTuple, so I've made peace with this :-)

[nblumhardt]

Thanks @cmeeren @bartelink 😊

[nblumhardt]

Spent some more time on this and measured the "empty pipeline" cost of a) the larger LogEvent class, and b) retrieval of Activity.Current in Logger.Write(), using the pipeline benchmark.

First up, dev:

Method	Mean	Error	StdDev	Gen0	Allocated
EmitLogEvent	174.3 ns	3.51 ns	4.57 ns	0.0598	376 B

The initial implementation:

Method	Mean	Error	StdDev	Gen0	Allocated
EmitLogEvent	199.9 ns	2.97 ns	2.78 ns	0.0648	408 B

So, about 14% slower and a little more alloc.

If we're prepared to move TraceId and SpanId off behind a single allocation, the benchmark does better:

Method	Mean	Error	StdDev	Median	Gen0	Allocated
EmitLogEvent	195.7 ns	3.92 ns	6.32 ns	192.4 ns	0.0610	384 B

Moving Exception (the other optional field) of behind the same allocation and tweaking the benchmark suggests that some execution time and allocation could be clawed back in the basic no exception, no trace scenario:

Method	Mean	Error	StdDev	Gen0	Allocated
EmitLogEvent	191.0 ns	1.72 ns	1.53 ns	0.0598	376 B

But, I'm not sure these results capture the real performance impact of making the additional small allocation rather growing the LogEvent class (number of allocations is as significant, or more, than total allocated bytes, and just about all monitored .NET apps will generate trace and span ids).

So, switching back to the original layout, but using non-nullable trace and span id fields gets to:

Method	Mean	Error	StdDev	Gen0	Allocated
EmitLogEvent	202.7 ns	4.08 ns	4.70 ns	0.0625	392 B

The execution time is within the same error bounds, but only 4.3% more space is allocated, improving on the original implementation's 8.5%.

--

Learned a little more about how trace and span ids are allocated on .NET Framework (and early .NET Core), which needs a little pondering.

[nblumhardt]

Pushed use of Nullable<T> higher up the stack, allowing some ?? operations to share the same conditional in their left-hand argument expressions, squeezing out a bit more performance:

Method	Mean	Error	StdDev	Gen0	Allocated
EmitLogEvent	182.4 ns	1.13 ns	1.06 ns	0.0625	392 B

Actually getting quite close to the original, now.

I think that while passing default for "no activity" and "no span" is fine on the LogEvent constructor, it's probably still best to expose them as nullable trace and span ids, since there's no obvious way for consumers to check for empty ActivityTraceId or ActivitySpanId values (they have to be == compared with default).

[nblumhardt]

Think this is now about as ready as it will get :-)

[nblumhardt]

Righto, forging ahead! Here's an incomplete list of remaining/downstream work we need to look at before RTMing this:

• Serilog.Sinks.OpenTelemetry - scrap the workarounds we currently use to ferry trace and span ids through to the background batching thread (Use LogEvent.TraceId and LogEvent.SpanId from Serilog 3.1 serilog-sinks-opentelemetry#110)
• Serilog.Extensions.Logging - capture activities when creating log events (Capture trace and span ids for Serilog 3.1 serilog-extensions-logging#227)
• Serilog.Formatting.Compact - add trace id @tr and span id @sp to output when present (Include Serilog 3.1 trace and span ids in output serilog-formatting-compact#56)
• Serilog.Formatting.Compact.Reader - read trace and span ids back into LogEvent (Support Serilog 3.1 trace @tr and span @sp ids serilog-formatting-compact-reader#36)
• Serilog.Expressions - @tr and @sp built-ins (Add support for Serilog 3.1 trace @tr and span @sp ids serilog-expressions#102)
• Serilog - update the README prominently

I suspect there are yet more scenarios out there that will call for either suppressing or explicitly specifying trace or span ids, but those will come out in the wash :)

[RehanSaeed]

@nblumhardt What version will this be released in? I'd like to point people to this new feature from https://github.com/RehanSaeed/Serilog.Enrichers.Span.

[nblumhardt]

Hi @RehanSaeed! Thanks for dropping by 👍

The package version that includes this is currently 3.1; I think before we can RTM it we need to add support in prerelease versions of the sinks people want to collect span information in, and get some feedback.

I'll push the first round of PRs (linked from the comment just above) and update the sinks I maintain (think that might just be the Seq sink right now), I'll also chime in on the other thread (in Serilog.AspNetCore) and ask what sinks people over there are using.

Once we've got a little bit of validation out in the field I don't think there will be much holding this up.

[joacar]

Great work with this! I'm on below version and can't se the Span and Trace id properties in Seq. I've configured ActivityTrackingOptions in logger for those properties. I'm I just a bit to eager and the Seq sink hasn't been updated? :)

Will these properties be propagated to the LogRecord using OpenTelemetry? And lastly, does Seq expose endpoint for gPRC and consuming the aforementioned LogRecord emitted from OTEL Agent?

Thanks!

<PackageVersion Include="Serilog" Version="3.1.0-dev-02071" />
<PackageVersion Include="Serilog.AspNetCore" Version="7.0.0" />
<PackageVersion Include="Serilog.Sinks.ApplicationInsights" Version="4.0.0" />
<PackageVersion Include="Serilog.Sinks.Console" Version="4.1.0" />
<PackageVersion Include="Serilog.Sinks.Seq" Version="6.0.0-dev-00266" />

[nblumhardt]

Hi @joacar! Those package versions do record trace and span ids in Seq for me when writing directly through a Serilog ILogger:

but the UI is a little different from what Seq shows for regular properties, and you need at least Seq 2023.3 (IIRC - I'm using 2023.4).

You will need to take a dependency on Seq.Extensions.Logging version 7.0.0-dev-10353 to override the version used by Serilog.AspNetCore if you're using the Microsoft.Extensions.Logging ILogger - the next major version (8.0.0) of that package will include support out of the box.

Seq exposes an OTLP gRPC endpoint - docs on how to find it are: https://docs.datalust.co/docs/ingestion-with-opentelemetry#grpc-endpoint (the http/protobuf endpoint described one paragraph earlier is available without any additional configuration on all platforms; gRPC requires seq config seq -k api.webServer -v Kestrel; seq service restart on Windows).

To quickly check whether trace and span ids are being picked up at all, you can use new JsonFormatter() as the ITextFormatter for your console sink, and you should see TraceId and SpanId root properties whenever those fields are present.

Still very early days for pulling all of these libraries together so you may find some rough edges; would be great to hear how you go, and if you hit issues please feel free to raise tickets here (or ping Seq support for Seq config help :-)).

[joacar]

Thanks for quick reply @nblumhardt ! I created a new project targeting .NET 8

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "SpanTrace": "Information"
    },
    "Console": {
      "IncludeScopes": true
    }
  }
}

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

    <PropertyGroup>
        <TargetFramework>net8.0</TargetFramework>
        <Nullable>enable</Nullable>
        <ImplicitUsings>enable</ImplicitUsings>
    </PropertyGroup>

    <ItemGroup>
      <PackageReference Include="Serilog" Version="3.1.0-dev-02078" />
      <PackageReference Include="Serilog.AspNetCore" Version="7.0.0" />
    </ItemGroup>

</Project>

using Serilog;
using Serilog.Events;
using Serilog.Formatting.Json;

var builder = WebApplication.CreateBuilder(args);

builder.Logging
    .AddConfiguration(builder.Configuration.GetSection("Logging"))
    .Configure(options =>
    {
        options.ActivityTrackingOptions = ActivityTrackingOptions.SpanId | ActivityTrackingOptions.TraceId;
    });

// builder.Host.UseSerilog((_,configuration) =>
// {
//     configuration
//         .MinimumLevel.Warning()
//         .MinimumLevel.Override("SpanTrace", LogEventLevel.Information)
//         .WriteTo.Console(new JsonFormatter()); //outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} {Properties}}");
// }, writeToProviders: true);

var app = builder.Build();
app.MapGet("/", (ILoggerFactory factory) =>
{
    var logger = factory.CreateLogger("SpanTrace");
    logger.LogInformation("Hello, world");
    return "Hello World!";
});

app.Run();

The code above prints

info: SpanTrace[0]
      => SpanId:8d76a8fb72d39fc1, TraceId:44c06015cbc16ccd4344aea231d5e40e => ConnectionId:0HMUAATBA7CQE => RequestPath:/ RequestId:0HMUAATBA7CQE:00000001
      Hello, world

and if I add the Serilog piece the output looks like this

info: SpanTrace[0]
      Hello, world
{"Timestamp":"2023-10-11T14:43:19.3062540+02:00","Level":"Information","MessageTemplate":"Hello, world","Properties":{"SourceContext":"SpanTrace","RequestId":"0HMUAAUIOUTV0:00000001","RequestPath":"/","ConnectionId":"0HMUAAUIOUTV0"}}

As you can see, the scope is dropped from the MEL and no properties are written from Serilog.

I couldn't find the package Seq.Extensions.Logging on NuGet, is it on a other feed?

Thanks!

[bartelink]

I couldn't find the package Seq.Extensions.Logging on NuGet, is it on a other feed?

Pretty sure he means Serilog.Extensions.Logging (which provides Use/AddSerilog) (the version number matches)

[joacar]

Thanks for that! Now it displays the ActivitTrackingOptions I've enabled for Serilog, but they are missing from default provider. Not a big deal since I guess most disable that (I do to, enabled it now for debugging)

info: SpanTrace[0] Hello, world
{"Timestamp":"2023-10-11T23:55:08.7648430+02:00","Level":"Information","MessageTemplate":"Hello, world","TraceId":"ad9e21f1f77d22b6f4855244aadfe665","SpanId":"ba403be4e02abeab","Properties":{"SourceContext":"SpanTrace","RequestId":"0HMUAKIU51MCG:00000001","RequestPath":"/","ConnectionId":"0HMUAKIU51MCG"}}

Will move on to testing Seq as well, but as long as I get the version right I should be up and running.
WIll there be an OTEL exporter for Seq? Perhaps there is already. I assume that is the way of handling logs "properly" using OTEL instead of writing directly from the logger.

Cheers

[nblumhardt]

@joacar writing directly from the logger is still the way to go, IMHO, since there are fewer moving parts involved. Seq supports OTLP natively now though, so you can use an OTLP logs exporter from the collector or SDK and get log events to Seq. We're working on adding tracing support currently.

[joacar]

I'll think about that. Historically I've always used ME.ILogger and from the to time questioned it and just use Serilog directly. What is the biggest win in your opinion using Serilog interface directly?
One thing I might be losing is LoggerMessages, or is there a way to utilize that in conjunction with Serilogger without need for MEL?
Will look it up during the day

Update: Found this which can likely be implemented in Serilog (if it isn't already - wouldn't surprise me!)

Thanks

[alexandrejobin]

Not sure what i'm doing wrong but I can't find the way to add TraceId et SpanId to the log. Is there a configuration I must set somewhere?