Serilog enrichers: the hidden cost of every log line
Serilog enrichers run on every log event, so an innocent property can quietly hit your database thousands of times an hour. What we learnt logging Ucommerce order IDs, buffering logs in memory and destructuring EF entities, with the fixes we now use on every project.
Tim Gaunt
If you write C# for a living, there's a fair chance Serilog is already in your solution, and a reasonable chance Seq is sitting at the other end of it. Both have been part of our standard toolkit at TSD for years. Structured logging has saved us more hours chasing production problems than I could count, and I'd recommend the pairing to anyone.
It has also bitten us. At least twice, and both times the culprit looked harmless in code review.
This post covers what happened, why it happened, and what we changed. It's written for C# developers, particularly anyone running Serilog on a busy e-commerce site, and it doesn't skip the detail so you may want to jump straight to the Serilog Ucommerce Property Enricher if you just want the code.
More logging made it worse
A few years ago we were trying to work out why a busy numismatic auction site (rare coins, with bidders who know exactly what they're after) slowed down at peak times. The obvious first step was more logging around the hot paths, so we added some. The slowdown got worse. We added more, and it got worse again.
It took longer than I'd like to admit to find the cause. We'd built a buffered logging setup that held events in memory and only shipped them to the server when something went wrong. On paper it's a clever idea, as the logging server only sees the events that matter and you still get the full lead-up to any error.
The catch is where those events wait. They sit in RAM, and with bids flooding in at peak, RAM was already under pressure. Every extra log line we added to diagnose the problem grew the buffer, which meant more memory pressure and more garbage collection, which slowed the site further. Our diagnostic tooling was feeding the very problem it was meant to find.
Every event gets constructed, enriched, held somewhere and serialised. That cost grows with traffic, at exactly the moment you can least afford it.
The enricher that queried the database
This is the one that prompted the post.
On our Ucommerce builds we add the order identifier to every log event. With OrderGuid on each event, one query in Seq pulls out an order's whole journey, from the first add to basket through checkout, payment callbacks and any processing that happens afterwards. When a customer rings to say their order "went a bit odd", that trail is the first thing we reach for.
We correlate on OrderGuid in preference to BasketId. Ucommerce clears the basket at checkout, so a BasketId is hard to tie back to anything once the order has been placed, whereas the OrderGuid stays with the order for life.
How we got hold of it was the problem. An enricher is a class implementing ILogEventEnricher, and its Enrich method runs for every log event that passes the minimum level check. The basket identifier comes from a cookie, so reading it costs next to nothing. Any property of the order itself (the id, guid, order number or total) has to come from the database, and our enricher was asking Ucommerce for the current order every time anything was logged.
NHibernate's caching is why this didn't jump out sooner, and it only helps up to a point. Ucommerce caches catalogue and configuration data across sessions (products, categories, countries and the like). Orders and their child collections have no second-level cache mapping at all. Repository queries are marked as cacheable, although the query cache only stores the ids a query returned, and NHibernate clears it whenever the order table is written to. Baskets live in that same table, so on a live shop a cached result rarely survives long enough to be reused.
Within a request, the session's first-level cache serves lookups by primary key and holds on to anything already loaded. A query still runs its SQL, and NHibernate reconciles the rows against the entities it's holding. On a quiet site the extra queries vanish into the noise. On a busy site with plenty of logging, an enricher that runs a query every time it fires can add dozens of round trips per request, multiplied by every shopper on the site at that moment.
Where enrichment sits in the pipeline makes it worse. Serilog checks the minimum level first, then builds and enriches the event, and only after that applies filters and hands it to the sinks. An event later discarded by Filter.ByExcluding(), or by a sink's restrictedToMinimumLevel, has already paid for enrichment. If Debug is enabled globally and trimmed back at the Seq sink, your enricher still runs for every Debug event.
Looking it up once per request
Most order data should be read fresh. The OrderGuid and OrderId are different, as once an order exists they never change, so fetching them more than once per request is wasted effort.
Our enricher now reads the basket id from the cookie, looks the basket up once, projects the handful of values it needs into a small object and parks that in HttpContext.Items. Every later event in the same request reads from there. Whether a request writes one log event or 100,000, the database sees one or two basket lookups at most.
Here it is in full. It targets Ucommerce on .NET Framework, hence HttpContext.Current, but the same shape carries over to IHttpContextAccessor on ASP.NET Core.
using Serilog.Core;
using Serilog.Events;
using System;
using System.Web;
using Ucommerce.Api;
using Ucommerce.EntitiesV2;
using Ucommerce.Infrastructure;
namespace TSD.Logging.Ucommerce
{
public class UcommerceOrderPropertiesEnricher : ILogEventEnricher
{
// The projected basket values are cached against this key in HttpContext.Items so that
// every log event raised during a request reuses a single basket lookup. The basket id is
// appended to the key because a request can switch baskets part way through - express
// checkout swaps to its own basket and restores the shopper's on the way out - and a
// basket-agnostic key would pair the new BasketId with the previous basket's values.
private const string OrderPropertiesKeyPrefix = "TSD.Logging.Ucommerce.UcommerceOrderPropertiesEnricher.OrderProperties:";
// Set in HttpContext.Items while the basket is being looked up. Ucommerce logs through Serilog
// too (its ExceptionLoggingInterceptor sits on the SessionProvider), so a log event raised by
// the lookup itself would otherwise come straight back in here and look the basket up again.
private const string LookupInProgressKey = "TSD.Logging.Ucommerce.UcommerceOrderPropertiesEnricher.LookupInProgress";
private readonly Func<HttpContextBase> _httpContextAccessor;
private readonly Func<PurchaseOrder> _basketAccessor;
public UcommerceOrderPropertiesEnricher()
: this(null, null)
{
}
/// <summary>
/// Test seam. Pass a context accessor and a basket accessor to exercise the enricher
/// without an ObjectFactory container or a real HttpContext.
/// </summary>
public UcommerceOrderPropertiesEnricher(Func<HttpContextBase> httpContextAccessor, Func<PurchaseOrder> basketAccessor)
{
_httpContextAccessor = httpContextAccessor ?? GetCurrentHttpContext;
_basketAccessor = basketAccessor ?? GetBasketForCurrentRequest;
}
// Resolved on every call, never held on to. Ucommerce registers ITransactionLibrary and
// everything beneath it - down to the NHibernate session - per web request, while this
// enricher lives for the whole process. Keeping the first instance resolved would share one
// request's session across every request that followed, hanging any request carrying a
// basket cookie until the site was restarted. The per-request cache below already limits
// this to one lookup per basket per request.
private static PurchaseOrder GetBasketForCurrentRequest()
{
return ObjectFactory.Instance.Resolve<ITransactionLibrary>().GetBasket(false);
}
public LogEventLevel MinimumLogLevel { get; set; } = LogEventLevel.Verbose;
public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
if (logEvent.Level < MinimumLogLevel)
return;
AddLogEventProperties(logEvent, propertyFactory);
}
private void AddLogEventProperties(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
{
try
{
var currentCtx = _httpContextAccessor();
if (currentCtx == null)
{
return;
}
if (!TryGetBasketIdFromHttpContext(currentCtx, out Guid basketId))
{
return;
}
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("BasketId", basketId));
// The basket is fetched at most once per basket per request; every later log event
// in the same request reads the values projected below straight out of HttpContext.Items.
var orderProperties = GetOrderProperties(currentCtx, basketId);
if (orderProperties == null || !orderProperties.HasOrder)
{
return;
}
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("CustomerId", orderProperties.CustomerId));
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("OrderNumber", orderProperties.OrderNumber));
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("OrderId", orderProperties.OrderId));
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("OrderGuid", orderProperties.OrderGuid));
logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty("OrderTotal", orderProperties.OrderTotal));
}
catch
{
}
}
private OrderProperties GetOrderProperties(HttpContextBase context, Guid basketId)
{
var items = context.Items;
if (items == null)
{
return ProjectBasket();
}
var key = OrderPropertiesKeyPrefix + basketId.ToString("N");
if (items[key] is OrderProperties cached)
{
return cached;
}
// An event raised by the lookup below gets the BasketId only, rather than a lookup of its own.
if (items[LookupInProgressKey] != null)
{
return null;
}
items[LookupInProgressKey] = true;
try
{
// A null basket is cached too, so a request without one does not repeat the lookup.
var projected = ProjectBasket();
items[key] = projected;
return projected;
}
finally
{
items.Remove(LookupInProgressKey);
}
}
private OrderProperties ProjectBasket()
{
PurchaseOrder order;
try
{
order = _basketAccessor();
}
catch
{
// A failed lookup is cached exactly like a missing basket. Without this, a request
// that cannot reach Ucommerce retries the basket on every log event it raises -
// worst during an incident, when log volume is highest and the lookup is likeliest
// to fail.
return new OrderProperties();
}
if (order == null)
{
return new OrderProperties();
}
return new OrderProperties
{
HasOrder = true,
CustomerId = order.Customer?.CustomerId,
OrderNumber = order.OrderNumber,
OrderId = order.OrderId,
OrderGuid = order.OrderGuid,
OrderTotal = order.OrderTotal
};
}
private static HttpContextBase GetCurrentHttpContext()
{
var current = HttpContext.Current;
if (current == null) return null;
return new HttpContextWrapper(current);
}
private bool TryGetBasketIdFromHttpContext(HttpContextBase context, out Guid basketId)
{
if (context == null)
{
basketId = Guid.Empty;
return false;
}
var cookieName = "basketid";
var cookie = context.Items[cookieName] as HttpCookie;
basketId = GetBasketIdFromCookie(cookie);
if (!basketId.Equals(Guid.Empty)) return true;
cookie = context.Request.Cookies[cookieName];
basketId = GetBasketIdFromCookie(cookie);
return !basketId.Equals(Guid.Empty);
}
private Guid GetBasketIdFromCookie(HttpCookie cookie)
{
if (cookie == null) return Guid.Empty;
try
{
return new Guid(cookie.Value);
}
catch
{
return Guid.Empty;
}
}
/// <summary>
/// The values projected from the basket, cached for the lifetime of the request only.
/// <see cref="HasOrder"/> is false for the sentinel cached when there is no basket.
/// </summary>
private sealed class OrderProperties
{
public bool HasOrder { get; set; }
public int? CustomerId { get; set; }
public string OrderNumber { get; set; }
public int OrderId { get; set; }
public Guid OrderGuid { get; set; }
public decimal? OrderTotal { get; set; }
}
}
}
Wiring it up is one line alongside your other enrichers:
var loggerConfig = new LoggerConfiguration()
// ...
.Enrich.With<UcommerceOrderPropertiesEnricher>()
.Enrich.FromLogContext()
.WriteTo.Seq(apiHost, apiKey: apiKey);
It's a good deal longer than the first version we wrote, and most of the extra lines are scar tissue. Four of them deserve an explanation.
The cache key includes the basket id. A request can switch baskets part way through (express checkout swaps to its own basket and restores the shopper's on the way out), and a key that ignored the basket would pair the new BasketId with the old basket's values. The same keying deals with a visitor's first add to basket, since the new basket's cookie produces a fresh key and the order gets picked up as soon as it exists. A request with no basket cookie never touches the database at all.
Ucommerce logs through Serilog as well. Its exception logging interceptor sits on the session provider, so anything the basket lookup logs comes straight back into the enricher, which would happily start another lookup. The LookupInProgress flag breaks the loop, and events raised during the lookup get the BasketId and nothing more.
Failed lookups are cached like a missing basket. Leave that out and a request that can't reach Ucommerce retries on every log event it raises, which is worst during an incident, when log volume is at its highest and the lookup is most likely to fail.
The last one hurt. Serilog creates an enricher once and keeps it for the life of the process. Ucommerce registers ITransactionLibrary, and everything beneath it down to the NHibernate session, per web request. An earlier version resolved the transaction library once and held on to it, so the first request's session was shared with every request after it, and any request carrying a basket cookie hung until the site was restarted. If your enricher depends on anything request-scoped, resolve it inside Enrich every time and let the per-request cache keep the cost down.
There's also a MinimumLogLevel property, which skips the work for events below a level your sinks are going to discard anyway. That's the pipeline-order problem from earlier, dealt with in code. The whole thing is wrapped in a try/catch too. Serilog would catch and report an enricher exception to SelfLog, but an enricher that throws on every event is a performance problem of its own.
One honest caveat. The enricher logs the order number, customer id and order total from the same lookup, and the total is a snapshot from the first lookup in the request. If the shopper adds something later in that request, the logged total won't reflect it. That's fine for spotting patterns, but don't treat it as the record of what was charged.
The other route is Serilog's LogContext. Push the property once, at the point in the request where you know the order exists, and Enrich.FromLogContext() attaches it to everything that follows. On Ucommerce we've stuck with the enricher. Baskets can appear or switch mid-request, and picking the right point to push the property gets fiddly fast.
Destructuring more than you meant to
Serilog's destructuring is one of its best features. Write {@Order} in a message template and Serilog walks the object's public properties, capturing them as structured data you can query in Seq.
It walks all of them, though.
Hand it an Entity Framework entity with lazy loading switched on and every navigation property it touches fires a query to load the related data, which is then destructured in turn. We've seen a developer log what looked like a single entity and send several related tables up to Seq, along with a batch of extra database queries nobody had planned for. Serilog's default maximum destructuring depth is ten levels, and by default there's no cap on string length or collection size, so a well-connected object graph gets very big very quickly.
Form posts are the other one to watch. Logging the posted model on a page with a file upload can mean the file goes along for the ride, often as a base64 string. On one project, users' uploads were landing in Seq inside log events, with payload sizes to match.
The Seq sink does protect the server up to a point. By default, Serilog.Sinks.Seq drops any event whose JSON goes over 256 KB (recent versions send a placeholder with a sample, so you can see something was lost). An event that squeaks in under that limit still gets serialised and sits in the sink's memory queue until it ships. You'll only spot it if you go looking.
Set your limits on day one:
Log.Logger = new LoggerConfiguration()
.Destructure.ToMaximumDepth(4)
.Destructure.ToMaximumStringLength(1000)
.Destructure.ToMaximumCollectionCount(20)
// enrichers, sinks etc.
.CreateLogger();
The numbers are a starting point, so tune them to your own data. Better still, keep EF entities out of {@...} templates altogether. Log the identifiers you need, or project the handful of properties that matter into an anonymous object:
_logger.Information("Customer updated {@Customer}",
new { customer.Id, customer.AccountType, customer.ModifiedOn });
Checking your log sizes after go-live
Limits only cover the cases you thought of. Once a system is live, we review the average and maximum size of its log events in Seq and dig into anything larger than it ought to be. We use this query:
select count(*) as Events,
round(sum(length(@Document)) * 0.000001, 2) as MBSize,
round(mean(length(@Document)) * 0.000001, 5) as AvgMBSize
from stream
group by Application, @MessageTemplate
order by Application, MBSize desc
@Document is the event's full JSON, so grouping by message template shows which kinds of event carry the weight, both in total and on average. length() counts characters, so the sizes are approximate, but they're plenty good enough for ranking. The Application grouping is there because one Seq instance collects logs from several of our sites; swap in whatever property you use to tell yours apart.
Run it in the first week, then again after any release that adds logging. In our experience the outliers are nearly always a destructured object that turned out bigger than anyone expected.
What we took away
Logging is code that runs in production, on every request, under peak load. Enrichers are the sharpest example of that, since one line of configuration attaches them to every event your application writes. Whatever an enricher does, it does thousands of times an hour.
Here's what we now do on every project:
- Treat enrichers as hot-path code that outlives every request. Cache anything slow for the request, and resolve request-scoped services inside
Enrich. - Cache identifiers that never change, such as OrderGuid, and treat anything volatile you cache alongside them, like the order total, as a snapshot.
- Set destructuring limits in configuration from the start, and keep EF entities out of
{@...}templates. - Check event sizes in Seq after go-live and whenever logging changes.
- Think twice before buffering logs in memory on a site that's already short of it.
None of this makes us any less keen on Serilog and Seq. We just read enricher code a lot more carefully in review than we used to.
If you're running Ucommerce or Umbraco Commerce and your logging has started to cost more than it tells you, we've untangled this a few times and are happy to compare notes.