Structured logging with .NET Framework System.Diagnostics(6 min read)

Structured logging (also sometimes called semantic logging) is a useful addition to the software development toolkit.

The latest release (2.2.0, and some 2.1.728) of Essential.Diagnostics adds structured tracing capabilities to the .NET Framework System.Diagnostics. It integrates seamlessly with existing tracing, including from the .NET Framework, and includes both producer-side extensions (to include in your application) and trace listener changes (to integrate with structured tracing systems).

The key new and updated packages are:

While the packages can be used independently, using both a producer and consumer in combination multiplies the benefits.

Core support

The support in Essential.Diagnostics.Core consists of a StructuredData class, and an associated IStructuredData interface.

This can be used to create, and then log, structure data, which will, in existing listeners, be rendered out in a structured format.

First, create a new console application project called "StructuredTracing.Example" and install the package:

PM> Install-Package Essential.Diagnostics.Core

Configure basic output, e.g. to the console and a rolling file:

<configuration>
  <system.diagnostics>
    <sharedListeners>
      <add name="console" type="System.Diagnostics.ConsoleTraceListener" />
      <add name="filelog"
type="Microsoft.VisualBasic.Logging.FileLogTraceListener,
Microsoft.VisualBasic, Version=9.0.0.0,
Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"
customLocation="Logs" location="Custom"
logFileCreationSchedule="Daily" />
    </sharedListeners>
    <sources>
      <source name="StructuredTracing.Example" switchValue="All">
        		<listeners>
          <add name="console"/>
          <add name="filelog"/>
        </listeners>
      </source>
    </sources>
    <trace autoflush="true"></trace>
  </system.diagnostics>
</configuration>

Next, trace some structured data to see the output:

var trace = new TraceSource("StructuredTracing.Example");
trace.TraceData(TraceEventType.Information, 1001,
  new StructuredData("City {Place} has coordinates {@Location}",
    "Brisbane",
    new { Latitude = -27.5, Longitude = 153.0 },
    Guid.NewGuid(),
    123.45));
Console.ReadLine();

Result (console):

StructuredTracing.Example Information: 1001 : City Brisbane has coordinates
(Latitude=-27.5 Longitude=153);
Extra1=6c8ec08e-06a1-4036-9fea-c01e772ce015 Extra2=123.45

Result (log file):

StructuredTracing.Example Information 1001 City Brisbane has coordinates
(Latitude=-27.5 Longitude=153);
Extra1=6c8ec08e-06a1-4036-9fea-c01e772ce015 Extra2=123.45

The trace information has been output, to out-of-the-box .NET Framework listeners, in a structured form, with items being destructured (@ operator) or output as key-value pairs as needed.

Combine with a structured trace listeners

The benefits of structured tracing are multiplied when you both produce structured data, and have a supporting trace listener that can make use of it.

The SeqTraceListener has been updated to take advantage of structured data, supporting the IStructuredData interface to send the full details to a Seq server.

This demo requires you to download and install Seq.

When ready, add the package to your application:

PM> Install-Package Essential.Diagnostics.SeqTraceListener

This package will automatically add a shared listener (and a sample source):

<add name="seq"
type="Essential.Diagnostics.SeqTraceListener,
Essential.Diagnostics.SeqTraceListener"
initializeData="http://localhost:5341"
apiKey=""
additionalProperties="MachineName,ThreadId,ProcessId,LogicalOperationStack"
/>

Add the listener to your source:

<source name="StructuredTracing.Example" switchValue="All">
		<listeners>
<add name="console" />
<add name="filelog" />
<add name="seq" />
</listeners>
</source>

With Seq running (turn on auto-refresh - the infinity button - to automatically see messages), run your program again.

Note: The SeqTraceListener runs asynchronously on a background thread; if the application ends too quickly (e.g. does not have the Console.ReadLine();), then it may not have time to log anything.

Result (Seq):

Structure-Tracing-Seq

Note that this is the same information as written to the Framework listeners, e.g. the Guid and Double values didn't have a name, so are just called 'Extra1' and 'Extra2'.

There are various overloads to the StructuredData constructor (shown below) that allow different ways to name items; for example, all of the "additionalProperties" (MachineName, ThreadId, etc) are named.

Fluent structured tracing

The other key package is Essential.Diagnostics.Structured, which adds a modern, fluent interface for writing traces (still compatible with .NET 2.0). There is also Essential.Diagnostics.StructuredExtensions, which is an alternative that adds some minimal extensions for existing tracing (and requires .NET 3.5).

To use the fluent interfaces, first use add the package:

PM> Install-Package Essential.Diagnostics.Structured

The following sample code gives a very basic example of some of the capabilities of the fluent interface. Add a new class called Worker, with the following content:

public class Worker
{
  IStructuredTrace trace;

  public Worker(IStructuredTrace<StandardEventId, Worker> trace)
  {
    this.trace = trace;
  }

  public void DoWork()
  {
    using (trace.BeginScope("TransactionId", Guid.NewGuid()))
    {
      trace.Warning(StandardEventId.ConfigurationWarning,
        new Dictionary<string, object>() {
{ "Limits", new[] { 12.34, 56.78 } }
},
        "Value {Value} exceeded lower limit",
34.56);
      trace.Critical(StandardEventId.SystemCriticalError,
new Exception(),
        "Unhandled exception");
    }
  }
}

To use this code, add the following to the main console program:

var worker = new Worker(
new AssemblyStructuredTrace<StandardEventId, Worker>()
);
worker.DoWork();

Note that the tracing class uses a generic interface and is designed to be inserted into a class via a dependency injection framework. The provided implementation uses the assembly name as the trace source (although you could provide an alternative implementation), so if it isn't working check the name of the assembly matches a source in the configuration, e.g. "StructuredTracing.Example".

The interface includes a method for each trace level (Verbose, Information, etc), with overloads for passing in both structured dictionaries and templated values, as well as convenience parameters for things such as exceptions. The interfaces also support strongly typed enumerations for event IDs.

Result (console):

StructuredTracing.Example Warning: 4000 : Value 34.56 exceeded lower limit;
Limits=[12.34,56.78]
StructuredTracing.Example Critical: 9100 : Unhandled exception;
Exception='System.Exception: Exception of type \'System.Exception\' was thrown.'

Result (Seq):

Structure-Tracing-Seq-2

Guidance

Structured (or semantic) tracing is an improvement, but it is not a silver bullet.

Search can find the relevant messages you are interested in, and, provided parameters are actually passed as parameters, tools like Seq can filter on the Type hash. You can even filter by values, as the positional parameters are well known *within that context*, e.g. {2} is always the product ID, or whatever.

Structured tracing makes things a little bit easier, by actually giving names to those parameters.

But the key is never the technology; all the latest and greatest tracing or logging technology is no help if you don't write useful tracing statements, with useful parameters, or if you don't even write any at all.

Deciding what and when to trace is the important part.

(Essential Diagnostics also provides some guidance on that as well, https://github.com/sgryphon/essential-diagnostics/blob/develop/docs/Logging-Levels.md)

Leave a Reply

Your email address will not be published. Required fields are marked *