SerilogTracing 1.1.0-dev-00282

SerilogTracing

SerilogTracing is a minimal tracing system that integrates Serilog with .NET's System.Diagnostics.Activity. You can use it to add distributed, hierarchical tracing to applications that use Serilog, and to consume traces generated by .NET components including HttpClient and ASP.NET Core.

Traces are written to standard Serilog sinks. Most sinks will currently flatten traces into individual spans, but it's easy to add full tracing support to sinks with capable back-ends, and the project ships tracing-enabled sinks for OpenTelemetry, Seq, and Zipkin.

Here's the output of the included example application in the standard System.Console sink:

The same trace displayed in Seq:

And in Zipkin:

Getting started

This section walks through a very simple SerilogTracing example. To get started we'll create a simple .NET 8 console application and install some SerilogTracing packages.

mkdir example
cd example
dotnet new console
dotnet add package SerilogTracing --prerelease
dotnet add package SerilogTracing.Expressions --prerelease
dotnet add package Serilog.Sinks.Console

Replace the contents of the generated Program.cs with:

using Serilog;
using Serilog.Templates.Themes;
using SerilogTracing;
using SerilogTracing.Expressions;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console(Formatters.CreateConsoleTextFormatter(TemplateTheme.Code))
    .CreateLogger();

using var _ = new ActivityListenerConfiguration().TraceToSharedLogger();

using var activity = Log.Logger.StartActivity("Check {Host}", "example.com");
try
{
    var client = new HttpClient();
    var content = await client.GetStringAsync("https://example.com");
    Log.Information("Content length is {ContentLength}", content.Length);

    activity.Complete();
}
catch (Exception ex)
{
    activity.Complete(LogEventLevel.Fatal, ex);
}
finally
{
    await Log.CloseAndFlushAsync();
}

Running it will print some log events and spans to the console:

dotnet run

Let's break the example down a bit.

Setting up the logger

The Serilog pipeline is set up normally:

using Serilog;
using Serilog.Templates.Themes;
using SerilogTracing;
using SerilogTracing.Expressions;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console(Formatters.CreateConsoleTextFormatter(TemplateTheme.Code))
    .CreateLogger();

The Formatters.CreateConsoleTextFormatter() function comes from SerilogTracing.Expressions; you can ignore this and use a regular console output template, but the one we're using here produces nice output for spans that includes timing information. Dig into the implementation of the CreateConsoleTextFormatter() function if you'd like to see how to set up your own trace-specific formatting, it's pretty straightforward.

Enabling tracing with ActivityListenerConfiguration.TraceToSharedLogger()

This line sets up SerilogTracing's integration with .NET's diagnostic sources, and starts an activity listener in the background that will write spans from the framework and third-party libraries through your Serilog pipeline:

using var _ = new ActivityListenerConfiguration().TraceToSharedLogger();

This step is optional, but you'll need this if you want to view your SerilogTracing output as hierarchical, distributed traces: without it, HttpClient won't generate spans, and won't propagate trace ids along with outbound HTTP requests.

You can also configure SerilogTracing to send spans through a specific ILogger:

using Serilog;
using SerilogTracing;
using SerilogTracing.Expressions;

await using var logger = new LoggerConfiguration()
    .WriteTo.Console(Formatters.CreateConsoleTextFormatter())
    .CreateLogger();

using var _ = new ActivityListenerConfiguration().TraceTo(logger);

Starting and completing activities

ILogger.StartActivity() is the main SerilogTracing API for starting activities. It works on any ILogger, and the span generated by the activity will be written through that logger, receiving the same enrichment and filtering as any other log event.

using var activity = Log.Logger.StartActivity("Check {Host}", "example.com");

StartActivity accepts a message template, just like Serilog, and you can capture structured properties by including them in the template.

The object returned from StartActivity() is a LoggerActivity, to which you can add additional structured data using AddProperty().

The LoggerActivity implements IDisposable, and if you let the activity be disposed normally, it will record the activity as complete, and write a span through the underlying ILogger.

In the example, because the activity needs to be completed before the Log.CloseAndFlushAsync() call at the end, we call Complete() explicitly on the success path:

try
{
    // ...
    activity.Complete();
}
catch (Exception ex)
{
    activity.Complete(LogEventLevel.Fatal, ex);
}

On the failure path, we call the overload of Complete() that accepts a level and exception, to mark the activity as failed and use the specified level for the generated log event.

Tracing-enabled sinks

These sinks have been built or modified to work well with tracing back-ends:

• Serilog.Sinks.Seq - call WriteTo.Seq() to send logs and traces to Seq; use Enrich.WithProperty("Application", "your app") to show service names in traces.
• SerilogTracing.Sinks.OpenTelemetry — call WriteTo.OpenTelemetry() and pass tracingEndpoint along with logsEndpoint to send traces and logs using OTLP.
• SerilogTracing.Sinks.Zipkin - call WriteTo.Zipkin() to send traces to Zipkin; logs are ignored by this sink.

Adding instrumentation for ASP.NET Core requests

If you're writing an ASP.NET Core application, you'll notice that the spans generated in response to web requests have very generic names, like HttpRequestIn. To fix that, first add SerilogTracing.Instrumentation.AspNetCore:

dotnet add package SerilogTracing.Instrumentation.AspNetCore --prerelease

Then add Instrument.AspNetCoreRequests() to your ActivityListenerConfiguration:

using var _ = new ActivityListenerConfiguration()
    .Instrument.AspNetCoreRequests()
    .TraceToSharedLogger();

Adding instrumentation for HttpClient requests

HttpClient requests are instrumented by default. To configure the way HttpClient requests are recorded as spans, remove the default instrumentation and add HttpClient instrumentation explicitly:

using var _ = new ActivityListenerConfiguration()
    .Instrument.WithDefaultInstrumentation(false)
    .Instrument.HttpClientRequests(opts => opts.MessageTemplate = "Hello, world!")
    .TraceToSharedLogger();

The message template for spans, and mappings from HttpRequestMessage and HttpResponseMessage into log event properties and the completion level can be configured.

Adding instrumentation for Microsoft.Data.SqlClient commands

Microsoft's client library for SQL Server doesn't generate spans by default. To turn on tracing of database commands, install SerilogTracing.Instrumentation.SqlClient:

dotnet add package SerilogTracing.Instrumentation.SqlClient --prerelease

Then add Instrument.SqlClientCommands() to your ActivityListenerConfiguration:

using var _ = new ActivityListenerConfiguration()
    .Instrument.SqlClientCommands()
    .TraceToSharedLogger();

Adding instrumentation for Npgsql commands

Npgsql is internally instrumented using System.Diagnostics.Activity, so no additional packages or steps are required to enable instrumentation of Npgsql commands. If you're missing spans from Npgsql, check that the "Npgsql" namespace isn't suppressed by your MinimumLevel.Override() configuration.

Formatting output

SerilogTracing includes extensions to Serilog.Expressions aimed at producing useful text and JSON output from spans:

dotnet add package SerilogTracing.Expressions --prerelease

For console output, Formatters.CreateConsoleTextFormatter() provides span timings in a pleasant ANSI-colored format:

Log.Logger = new LoggerConfiguration()
    // The `Formatters` class is from `SerilogTracing.Expressions`
    .WriteTo.Console(Formatters.CreateConsoleTextFormatter(TemplateTheme.Code))
    .CreateLogger();

Alternatively, TracingNameResolver can be used with ExpressionTemplate to create text or JSON output. The example above expands into the (admittedly quite dense) template below:

var formatter = new ExpressionTemplate(
    "[{@t:HH:mm:ss} {@l:u3}] " +
    "{#if IsRootSpan()}\u2514\u2500 {#else if IsSpan()}\u251c {#else if @sp is not null}\u2502 {#else}\u250A {#end}" +
    "{@m}" +
    "{#if IsSpan()} ({Milliseconds(Elapsed()):0.###} ms){#end}" +
    "\n" +
    "{@x}",
    theme: TemplateTheme.Code,
    nameResolver: new TracingNameResolver());

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console(formatter)
    .CreateLogger();

For an example showing how to produce JSON with ExpressionTemplate, see the implementation of ZipkinSink in this repository, and this article introducing Serilog.Expressions JSON support.

How an Activity becomes a LogEvent

Applications using SerilogTracing add tracing using ILogger.StartActivity(). These activities are always converted into LogEvents and emitted through the original ILogger that created them. .NET libraries and frameworks add tracing using System.Diagnostics.ActivitySources. These activities can also be emitted as LogEvents using SerilogTracing.ActivityListenerConfiguration.

Mapping trace concepts to event properties

Traces are collections of spans, connected by a common trace id. SerilogTracing maps the typical properties associated with a span onto Serilog LogEvent instances:

Levelling for external activity sources

SerilogTracing can consume activities from .NET itself, and libraries that don't themselves use SerilogTracing. By default, you'll see spans for all activities, from all sources, in your Serilog output.

To "turn down" the level of tracing performed by an external activity source, use SerilogTracing's InitialLevel configuration to set a level for spans from that source:

    .InitialLevel.Override("Npgsql", LogEventLevel.Debug)

In this example, when activities from the Npgsql activity source are assigned an initial level of Debug, they'll be suppressed unless your Serilog logger has debug logging enabled.

Why is this an initial level?

The initial level assigned to a source determines whether activities are created by the source. When the activity is completed, it may be recorded at a higher level; for example, a span created at an initial Information level may complete as an Error (but not at a lower level such as Debug, because doing so may suppress the span cause the trace hierarchy to become incoherent).

What's the relationship between SerilogTracing and OpenTelemetry?

OpenTelemetry is a project that combines a variety of telemetry data models, schemas, APIs, and SDKs. SerilogTracing, like Serilog itself, has no dependency on the OpenTelemetry SDK, but can output traces using the OpenTelemetry Protocol (OTLP). From the point of view of SerilogTracing, this is considered to be just one of many protocols and systems that exist in the wider Serilog ecosystem.

If you're working in an environment with deep investment in OpenTelemetry, you might consider using the OpenTelemetry .NET SDK instead of SerilogTracing. If you're seeking lightweight, deliberate instrumentation that has the same crafted feel and tight control offered by Serilog, you're in the right place.

SerilogTracing.Sinks.OpenTelemetry

SerilogTracing includes a fork of Serilog.Sinks.OpenTelemetry. This is necessary (for now) because Serilog.Sinks.OpenTelemetry only supports the OTLP logs protocol: SerilogTracing.Sinks.OpenTelemetry extends this with support for OTLP traces.

Who is developing SerilogTracing?

SerilogTracing is an open source (Apache 2.0) project that welcomes your ideas and contributions. It's built by @nblumhardt (also a Serilog maintainer), @liammclennan and @kodraus from Datalust, the company behind Seq.

SerilogTracing is not an official Serilog or Datalust project, but our hope for it is that it can serve as a validation and a basis for deeper tracing support in Serilog in the future.