Trace Context in Logs

Adding trace context to application logs provides the ability to correlate the log messages from a single transaction, and if sampled, the log messages to the transaction trace detail.

The AppOptics .NET agent offers several options to include trace context into logs managed by several popular .NET logging frameworks, and provides a custom SDK call which can be used if the automatic options do not support your logger.

How to Add Trace Context to Logs

There are 3 options to include trace context into logs:

Automatic Insert

When enabled, the .NET agent automatically inserts the trace context to the end of the layout’s output template. As a result, all log messages will have the Trace ID appended at the end.

This feature is disabled by default, more detail can be found in the Configuration section.

Automatic Attribute

.NET agent automatically adds %property{ao.traceId:long} attribute for Log4net or {aoTraceIdLong} attribute for Serilog to the Logging Event object. The attribute contains the Trace ID value. Such a value can then be included in the logging layout by using pattern such as %property{ao.traceId:long} for Log4net or {aoTraceIdLong} for Serilog.

These features are disabled by default, more detail on how to enable these options can be found in the Configuration section.

Using the SDK

Trace context can be manually inserted into log messages; this can be used if your application logger is not supported by the automatic options above. The string value of the Trace context can be obtained using the SDK GetLogTraceId method. Note that if the agent is not available or not started propertly, the value will be an empty string.

Supported Frameworks

Log4net

When using automatic insert, the PatternLayout is updated with %property{ao.traceId:long} at the end and when a message is logged the Trace ID will be at the end of the log message.

<layout type="log4net.Layout.PatternLayout">
     <conversionPattern value="%date [%thread] %level %logger - %message %property{ao.traceId:long} %newline" />
</layout>

Output:

2019-05-23 15:02:49,708 [6] INFO WebApp.Controllers.HelloController - hello world ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1

When using automatic attribute, the PatternLayout layout must be manually updated %property{ao.traceId:long}

<layout type="log4net.Layout.PatternLayout">
     <conversionPattern value="%date [%thread] %level %logger %property{ao.traceId:long} - %message%newline" />
</layout>

Output:

2019-05-23 15:02:49,708 [6] INFO WebApp.Controllers.HelloController ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 - hello world

The %property{ao.traceId:<format>} allows the following formats:

  • %property{ao.traceId} - output contains only the log Trace ID

    2019-05-23 15:02:49,708 [6] INFO WebApp.Controllers.HelloController C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 - hello world

  • %property{ao.traceId:long} - default format used for auto inserting, the log Trace ID is prefixed with ao.traceId=

    2019-05-23 15:02:49,708 [6] INFO WebApp.Controllers.HelloController ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 - hello world

  • %property{ao.traceId:json} - output is a JSON object

    2019-05-23 15:02:49,708 [6] INFO WebApp.Controllers.HelloController {"ao":{"traceId":"C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1"}} - hello world

When using the XmlLayout layout and automatic attribute is enabled

<layout type="log4net.Layout.XmlLayout"></layout>

Output:

<log4net:event logger="WebApp.Controllers.HelloController" timestamp="2019-05-27T15:35:22.0626731-07:00" level="INFO" thread="6" domain="/LM/W3SVC/5/ROOT-1-132034701117372141" username="IIS APPPOOL\MVC5_TestLog4net">
<log4net:message>hello world</log4net:message>
   <log4net:properties>
       <log4net:data name="log4net:HostName" value="TEST-MACHINE" />
       <log4net:data name="ao.traceId" value="C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1" />
   </log4net:properties>
</log4net:event>

When using an SimpleLayout layout and automatic insert is enabled

<layout type="log4net.Layout.SimpleLayout"></layout>

Output:

INFO - hello world ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1

Serilog 2.8.0

Note

This feature is only available when log events are enriched with built-in Serilog.Context.LogContext enricher. When creating logger object, a call to .Enrich.FromLogContext() method must be added.

When using automatic insert, the output template is updated at runtime to contain {aoTraceIdLong} attribute

// Output template

string outTemplate = "{Timestamp:HH:mm} [{Level}] {Message}{NewLine}{Exception}";

// Create serilog logger using provided output template

Log.Logger = new LoggerConfiguration()
               .Enrich.FromLogContext()
               .WriteTo.File(logFile, rollingInterval: RollingInterval.Infinite, outputTemplate: outTemplate)
               .CreateLogger();

Log.Information("hello world");

Output:

15:55 [Information] hello world ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1

When using automatic attribute, the output template must be manually updated with {aoTraceIdLong} attribute

// Output template

string outTemplate = "{Timestamp:HH:mm} [{Level}] {aoTraceIdLong} {Message}{NewLine}{Exception}";

// Create serilog logger using provided output template

Log.Logger = new LoggerConfiguration()
               .Enrich.FromLogContext()
               .WriteTo.File(logFile, rollingInterval: RollingInterval.Infinite, outputTemplate: outTemplate)
               .CreateLogger();

Log.Information("hello world");

Output:

15:55 [Information] ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 hello world

The {aoTraceId<format>} allows the following formats:

  • {aoTraceId} - output contains only log trace context

    15:55 [Information] C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 hello world

  • {aoTraceIdLong} - default format used for auto inserting, the log Trace ID is prefixed with ao.traceId=

    15:55 [Information] ao.traceId=C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1 hello world

  • {aoTraceIdJson} - output is a JSON object

    15:55 [Information] {"ao":{"traceId":"C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1"}} hello world

When using automatic attribute in combination with CompactJsonFormatter formatter class, trace context is added as aoTraceId property of the JSON record

Log.Logger = new LoggerConfiguration()
               .Enrich.FromLogContext()
               .WriteTo.File(new CompactJsonFormatter(), logFile)
               .CreateLogger();

Log.Information("hello world");

Output:

{"@t":"2019-05-28T21:44:00.3293747Z","@mt":"hello world","aoTraceId":"C2E7EA546BC9C31BC18E1877C3191A0C6E952C08-1"}