Serilog Best Practices

Serilog is a structured logging library for Microsoft .NET and has become the preferred logging library for .NET at Checkout.com.. It supports a variety of logging destinations, referred to as Sinks, from standard console and files based sinks to logging services such as Datadog.

This guide started off as an article in our engineering handbook and after receiving positive feedback internally, I decided to release it on my blog.

Contents

Standard log properties

Standardising log event properties enables you to get the most out of log search and analysis tools. Use the following Properties where applicable:

Many of the above attributes come from Serilog’s own extensions, for example Serilog Timings (used to time operations) and Serilog request logging.

Logging fundamentals

Log key events

In general, log key events that provide insight into your application and user behaviour, for example:

• Major branching points in your code
• When errors or unexpected values are encountered
• Any IO or resource intensive operations
• Significant domain events
• Request failures and retries
• Beginning and end of time-consuming batch operations

Choose an appropriate logging level

Be generous with your logging but be strict with your logging levels. In almost all cases the level of your logs should be Debug. Use Information for log events that would be needed in production to determine the running state or correctness of your application and Warning or Error for unexpected events, such as Exceptions.

Note that the Error level should be reserved for events that you intend to act on. If something becomes normal application behaviour (e.g. a request failing input validation) you should downgrade the log level to reduce log “noise”.

Timing operations

Log every resource-intensive operation such as IO, in your applications, alongside your metrics code. This is very useful when running applications locally to see application bottlenecks or what is eating into response time. The Serilog Timings library provides a convenient way to do this:

using (_logger.TimeDebug("Sending notification to Slack channel {Channel} with {WebhookUrl}", _slackOptions.Channel, _slackOptions.WebhookUrl))
using (_metrics.TimeIO("http", "slack", "send_message"))
{

}

Source Context

The SourceContext property is used to track the source of the log event, typically the C# class from where the logger is being used. It’s common to inject Serilog’s ILogger into classes using Dependency Injection. To ensure the SourceContext is set correctly, use the ForContext extension:

public TheThing(ILogger logger)
{
    _logger = logger?.ForContext<TheThing>() ?? throw new ArgumentNullException(nameof(_logger));
}

HTTP Logging

Use the Serilog request logging middleware to log HTTP requests. This automatically includes many of the HTTP attributes listed above and produces the following log message:

HTTP POST /payments responded 201 in 1348.6188 ms

Add the following to your application startup to add the middleware:

public void Configure(IApplicationBuilder app)
{
    app.UseHealthAndMetricsMiddleware();
    app.UseSerilogRequestLogging();
    app.UseAuthentication();
    app.UseMvc();
}

Note that the Serilog middleware is added after the health and metrics middleware. This is to avoid generating logs every time your health check endpoints are hit by AWS load balancers.

Logging HTTP Resources

The Serilog middleware by default logs the request path. If you do have a need to see all requests for a particular endpoint in your application you may have a challenge if the path contains dynamic parameters such as identifiers.

To get around this, log the resource name which by convention in our applications is the Name attribute given to the corresponding route. This is retrieved like so:

public static string GetMetricsCurrentResourceName(this HttpContext httpContext)
{
    if (httpContext == null)
        throw new ArgumentNullException(nameof(httpContext));

    Endpoint endpoint = httpContext.Features.Get<IEndpointFeature>()?.Endpoint;

#if NETCOREAPP3_1
    return endpoint?.Metadata.GetMetadata<EndpointNameMetadata>()?.EndpointName;
#else
    return endpoint?.Metadata.GetMetadata<IRouteValuesAddressMetadata>()?.RouteName;
#endif
}

Avoid excessive production logging

Logs help to reason about your application and diagnose issues. You should review your production logs regularly to ensure they provide value. It’s all too easy to add additional logging during the investigation of complex issues and not clean it up afterwards.

Bad actors logging excessively can also impact the health of logging systems, which are often shared between teams. It’s helpful to establish standards on what events should be logged at INFO level. Remember, you can always dial up your logging to DEBUG if you need.

Finally, rather than adding additional log events to log information at different points in the request lifecycle, favour using Serilog’s diagnostic context feature (discussed below) to collapse contextual information into a single completion log.

Create log specific objects when destructuring

Serilog supports destructuring, allowing complex objects to be passed as parameters in your logs.

This feature should be used with caution. It’s not uncommon for sensitive information to be included in logs because an object that is defined outside of the scope of the logging code is extended.

When destructuring, be explicit about the data that is logged by creating log specific objects (anonymous objects work great):

For example, instead of:

_logger.Information("Processing HTTP request with data {@Request}", httpContext.Request);

use:

var requestData = new { Path = httpContext.Request.Uri.AbsolutePath, User = httpContext.Request.User.GetUserId()  };
_logger.Information("Processing HTTP request with data {@Request}", requestData);

Enrich your logs

Pushing additional information into your logs can help provide additional context about a specific event.

Standard Serilog enrichers

You can use enrichers to enrich all log events generated by your application. We recommend use of the following Serilog enrichers:

• Log Context enricher - Built in to Serilog, this enricher ensures any properties added to the Log Context are pushed into log events
• Environment enrichers - Enrich logs with the machine or current user name

Enrichers can be specified using the Enrich.With fluent API of the Serilog LoggerConfiguration or via your appsettings.json file (recommended):

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console"
    ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName"
    ],
    "Properties": {
      "ApplicationName": "Gateway API"
    }
  }
}

Enrich from global properties

You can also specify properties globally. The above snippet from appsettings.json demonstrates how we commonly set the ApplicationName property. In some cases, we need to calculate properties on startup, which can be done using the Fluent API:

loggerConfiguration.ReadFrom.Configuration(hostContext.Configuration)
    .EnrichWithEventType()
    .Enrich.WithProperty("Version", ReflectionUtils.GetAssemblyVersion<Program>());

Correlating logs

In order to correlate logs that belong to the same request, even across multiple applications, add a CorrelationId property to your logs.

In HTTP applications we typically map this from the HttpContext.TraceIdentifier property. This is passed between internal APIs using the Cko-Correlation-Id header. We use the following extension to obtain the _current_correlation ID:

public static string GetCorrelationId(this HttpContext httpContext)
{
    httpContext.Request.Headers.TryGetValue("Cko-Correlation-Id", out StringValues correlationId);
    return correlationId.FirstOrDefault() ?? httpContext.TraceIdentifier;
}

Note that if the application is public facing, you should not rely on the provided correlation ID header.

To ensure that the correlation ID is pushed into every log event we use the following middleware that uses Serilog’s LogContext (discussed in more detail later in this article):

public class RequestLogContextMiddleware
{
    private readonly RequestDelegate _next;

    public RequestLogContextMiddleware(RequestDelegate next)
    {
        _next = next;
    }

    public Task Invoke(HttpContext context)
    {
        using (LogContext.PushProperty("CorrelationId", context.GetCorrelationId()))
        {
            return _next.Invoke(context);
        }
    }
}

Message Templating

Log messages should provide a short description of the event. We commonly see developers create overly verbose messages as means of including additional data in the event, for example:

_logger.Information("Storing payment state in Couchbase for Payment ID {PaymentId} and current state {State}", paymentId, state);

Instead you can use ForContext (or the property bag enricher at the bottom of this article) to still include the data but have terser messages:

_logger
    .ForContext("PaymentId", paymentId)
    .ForContext("State", state)
    .Information("Storing payment state in Couchbase");

Message Template Recommendations

Fluent Style Guideline

Good Serilog events use the names of properties as content within the message to improve readability and make events more compact, for example:

_logger.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

Sentences vs. Fragments

Log event messages are fragments, not sentences; for consistency with other libraries that use Serilog, avoid a trailing period/full stop when possible.

Templates vs. Messages

Serilog events have a message template associated, not a message. Internally, Serilog parses and caches every template (up to a fixed size limit). Treating the string parameter to log methods as a message, as in the case below, will degrade performance and consume cache memory. For example, avoid:

Log.Information("The time is " + DateTime.Now);

Instead use message properties:

Log.Information("The time is {Now}", DateTime.Now);

Aside from the performance overhead of using string concatenation/interpolation within your log messages it also means that a consistent event type cannot be calculated (see Event Type Enricher) making it impossible to find all the logs of a particular type.

Log and Diagnostic Context

Serilog supports two context-aware features that can be used to enhance your logs.

Log Context

The LogContext can be used to dynamically add and remove properties from the ambient “execution context”; for example, all messages written during a transaction might carry the id of that transaction, and so-on.

The RequestLogContextMiddleware presented above demonstrates how we push the CorrelationId of the request into the LogContext at the beginning of the request. This ensures that all logs within that request include that property.

More information can be found on the Serilog wiki.

Diagnostic Context

One challenge with logging is that context is not always known upfront. For example, during the processing of a HTTP request, additional context is gained as we progress through the HTTP pipeline such as knowing the identity of the user. Whilst LogContext would all us to create new contexts as additional information becomes available, this information would only be available in _subsequent_log entries. This commonly leads to an increase in the number of logs, just to capture everything about the overall request or operation.

The diagnostic context is provides an execution context (similar to LogContext) with the advantage that it can be enriched throughout its lifetime. The request logging middleware then uses this to enrich the final “log completion event”. This allows us to collapse many different log operations into a single log entry, containing information from many points in the request pipeline, for example:

Here you can see that not only have the HTTP properties emitted by the middleware but also application data such as AcquirerId, MerchantName and ResponseCode. These data points come from different points in the request but are pushed into the diagnostic context via the IDiagnosticContext interface:

public class HomeController : Controller
{
    readonly IDiagnosticContext _diagnosticContext;

    public HomeController(IDiagnosticContext diagnosticContext)
    {
        _diagnosticContext = diagnosticContext ?? throw new ArgumentNullException(nameof(diagnosticContext));
    }

    public IActionResult Index()
    {
        // The request completion event will carry this property
        _diagnosticContext.Set("CatalogLoadTime", 1423);

        return View();
    }

Using Diagnostic Context in non-HTTP applications

Diagnostic Context is not limited to usage within ASP.NET Core. It can also be used in non-HTTP applications in a very similar way to the request logging middleware. For example, we are using it to generate a completion log event in our SQS consumers.

Configuration

Serilog can be configured using either a Fluent API or via the Microsoft Configuration system. We recommend using the configuration system since the logging configuration can be changed without releasing a new version of your application.

To do so, add the Serilog.Settings.Configuration package and configure Serilog as below:

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .UseSerilog((hostContext, loggerConfiguration) =>
        {
            loggerConfiguration.ReadFrom.Configuration(hostContext.Configuration);
        })
        .ConfigureAppConfiguration((hostingContext, config) =>
        {
            config
                .AddEnvironmentVariables(prefix: "FLOW_")
                .AddAwsSecrets();
        })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();  
        });

You can now configure Serilog via any supported configuration provider. Typically we use appsettings.json for global settings and configure the actual sinks via environment variables in production (since we don’t want to use our remote logging services when running locally):

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.Datadog.Logs"
    ],
    "MinimumLevel": {
      "Default": "Information"
    },
    "WriteTo": [
      {
        "Name": "Console"
      }
    ],
    "Enrich": [
      "FromLogContext",
      "WithMachineName"
    ],
    "Properties": {
      "ApplicationName": "Flow API"
    }
  }
}

Production logging

When deploying your applications in production, ensure that logging is configured accordingly:

• Console logging should be restricted to Error. In .NET writing to Console is a blocking call and can have a significant performance impact.
• Global logging should be configured for Information and above.

It’s understood that during the release of a new project you may need additional information to build confidence in the solution or to diagnose any expected teething issues. Rather than upgrading your log entries to Information for this, consider enabling Debug level for a limited period of time.

A common question heard from developers is how they can dynamically switch logging levels at runtime. Whilst this is possible, it can also be achieved using blue/green deployments. Configure and deploy the non-active environment with the reduced log level and then switch a portion or all of the traffic via weighted target groups.

When logs become more than logs

Logs can provide a lot of insight into an application and in many cases be sufficient to handle day-to-day support requests or troubleshooting. There are however cases where logs are not the right tool for the job, with a number of warning signs:

• You find yourself opening up application logs to non-technical users
• Logs are being used to generate application metrics
• More information is being “stuffed” into logs to satisfy common support requests or reporting requirements

In these cases, you may need to consider dedicated tooling for your product. A number of teams have developed “Inspector” like applications that aggregate key system and business data together to handle BAU requests that can be provided to non-technical stakeholders. Additionally you may find the need to push data from your application into reporting and analytics tools.

The effectiveness of your logs is both what you log and what you don’t log.

Other tools and utilities

Use Seq locally

Seq is a free (for local use) logging tool created by the author of Serilog. It provides advanced search and filtering capabilities as well as full access to structured log data. Whilst our logging requirements now extend beyond what Seq can offer, it is still a great option for testing locally.

We usually spin up Seq in docker as part of a separate docker-compose file (docker-compose-logging.hml):

version: "3.5"

services:

seq:
    image: datalust/seq:latest
    container_name: seq
    ports:
    - '5341:80'
    environment:
    - ACCEPT_EULA=Y
    networks:
    - gateway-network

networks:
gateway-network:
    name: gateway-network

And configure our appsettings.Development.json file to use the Seq sink:

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.Seq"
    ],
    "MinimumLevel": {
      "Default": "Debug",
      "Override": {
        "Microsoft": "Warning"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "Seq",
        "Args": {
          "serverUrl": "http://localhost:5341",
          "apiKey": "none"
        }
      }
    ]
  }
}

Event Type Enricher

Often we need to uniquely identify logs of the same type. Some sinks such as Seq do this automatically by hashing the message template. To replicate the same behaviour in other sinks we created the following enricher which uses the Murmerhash algorithm:

internal class EventTypeEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        if (logEvent is null)
            throw new ArgumentNullException(nameof(logEvent));

        if (propertyFactory is null)
            throw new ArgumentNullException(nameof(propertyFactory));

        Murmur32 murmur = MurmurHash.Create32();
        byte[] bytes = Encoding.UTF8.GetBytes(logEvent.MessageTemplate.Text);
        byte[] hash = murmur.ComputeHash(bytes);
        string hexadecimalHash = BitConverter.ToString(hash).Replace("-", "");
        LogEventProperty eventId = propertyFactory.CreateProperty("EventType", hexadecimalHash);
        logEvent.AddPropertyIfAbsent(eventId);
    }
}

Property Bag Enricher

In cases where you want to add multiple properties to your log events, use the PropertyBagEnricher:

public class PropertyBagEnricher : ILogEventEnricher
{
    private readonly Dictionary<string, Tuple<object, bool>> _properties;

    /// <summary>
    /// Creates a new <see cref="PropertyBagEnricher" /> instance.
    /// </summary>
    public PropertyBagEnricher()
    {
        _properties = new Dictionary<string, Tuple<object, bool>>(StringComparer.OrdinalIgnoreCase);
    }

    /// <summary>
    /// Enriches the <paramref name="logEvent" /> using the values from the property bag.
    /// </summary>
    /// <param name="logEvent">The log event to enrich.</param>
    /// <param name="propertyFactory">The factory used to create the property.</param>
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        foreach (KeyValuePair<string, Tuple<object, bool>> prop in _properties)
        {
            logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(prop.Key, prop.Value.Item1, prop.Value.Item2));
        }
    }

    /// <summary>
    /// Add a property that will be added to all log events enriched by this enricher.
    /// </summary>
    /// <param name="key">The property key.</param>
    /// <param name="value">The property value.</param>
    /// <param name="destructureObject">
    /// Whether to destructure the value. See https://github.com/serilog/serilog/wiki/Structured-Data
    /// </param>
    /// <returns>The enricher instance, for chaining Add operations together.</returns>
    public PropertyBagEnricher Add(string key, object value, bool destructureObject = false)
    {
        if (string.IsNullOrEmpty(key)) throw new ArgumentNullException(nameof(key));

        if (!_properties.ContainsKey(key)) _properties.Add(key, Tuple.Create(value, destructureObject));

        return this;
    }
}

Usage:

_logger
    .ForContext(
      new PropertyBagEnricher()
        .Add("ResponseCode", response?.ResponseCode)
        .Add("EnrollmentStatus", response?.Enrolled)
    )
    .Warning("Malfunction when processing 3DS enrollment verification");

Request Log Enricher

The Serilog request logging middleware allows a function to be provided that can be used to add additional information from the HTTP request to the completion log event. We use this to log the ClientIP, UserAgent and Resource properties:

public static class LogEnricher
{
    /// <summary>
    /// Enriches the HTTP request log with additional data via the Diagnostic Context
    /// </summary>
    /// <param name="diagnosticContext">The Serilog diagnostic context</param>
    /// <param name="httpContext">The current HTTP Context</param>
    public static void EnrichFromRequest(IDiagnosticContext diagnosticContext, HttpContext httpContext)
    {
        diagnosticContext.Set("ClientIP", httpContext.Connection.RemoteIpAddress.ToString());
        diagnosticContext.Set("UserAgent", httpContext.Request.Headers["User-Agent"].FirstOrDefault());
        diagnosticContext.Set("Resource", httpContext.GetMetricsCurrentResourceName());
    }
}

Usage

app.UseSerilogRequestLogging(opts
  => opts.EnrichDiagnosticContext = LogEnricher.EnrichFromRequest);