Seq 2.1 Refresh

Since Seq 2.0 shipped a couple of weeks ago, enough small fixes and improvements have been collected to make a new point release.

Seq 2.1 is ready to download, and includes:

  • Send to app is back (#301)
  • Find with adjacent works in locales that use comma as a digit separator; enfin! (#194)
  • Downgrading to the free version now completes successfully even if the admin user has been deleted (#302)
  • TotalMilliseconds() enables parsing of .NET TimeSpan properties that have been serialized to strings (#152)
  • Refreshing the /login page now works as expected (#303)
  • Seq will now stop recording events when a (configurable) minimum disk space limit is reached – by default, 128 MB (#304)

There are a some minor performance and usability tweaks in there too, including some pixel shuffling for better in-browser scaling at 50, 75 and 90% on the events screen.

Hope you’re enjoying the new release! Comments and feedback welcome as always :-)

Announcing Seq 2 RTW

It’s with pleasure I can announce that the RTW build of Seq 2.0 is now available.

What is Seq?

Seq is a log server designed specifically to take advantage of modern structured logging techniques. Libraries like Serilog and SLAB produce log events that are not only readable messages, but richly structured objects that can be searched and correlated with ease. Seq is the fastest way for .NET teams to capture and investigate these logs when debugging code in complex environments.

With Seq it’s trivially easy to find all events raised in a particular HTTP request, from a particular machine, or when processing a particular order, for example. Not only that, but queries unimaginable before the rise of structured logging – “show me all the orders processed with an item over $100” – can be expressed in a clean C#-style syntax and answered directly from logs.

What’s New?

The centrepiece of the 2.0 release is a completely redesigned query interface, featuring auto-completion and syntax help for filtering, click-to-apply signals, and easier sharing for users working in larger teams.

Seq 2.0

Seq 2.0 also paves the way to much easier temporal navigation with a new timeline view and to-the-millisecond date and time filtering.

In addition, almost every corner of the interface has been re-thought, and many small improvements made to ergonomics and usability.

Installing and Upgrading

If you’re not using Seq today, you can install it for free under the complimentary single-user license, or get a trial key that enables authentication and other team-oriented features on our website.

If you purchased Seq in the last year, you can upgrade under your existing license: just install the new version and your data will be migrated in place. Easy!

If you’ve used up your 12 months included upgrades already – you’re in luck: to celebrate the release of the new version we’re offering existing customers discounted upgrade pricing this month. Email Support and we’ll organize it for you and make sure everything goes seamlessly.

Documentation and Support

With this release we’re launching a new combined documentation and forum site at docs.getseq.net. Check out the new Getting Started page and keep an eye out for new content as we migrate it from the older Confluence site.

Thanks and Acknowledgements

This release was made possible by our wonderful customers, and a brave bunch of early adopters who’ve given us invaluable feedback and bug reports during the beta period. Thank you all!

Download Seq 2.0 now.

Filtering with Signals in Seq 2

Structured logs are designed for easy filtering and correlation. If you monitor apps in multiple environments for example, you’ll pretty quickly turn to structured properties like Environment as a way to distinguish between logs from different locations:

Log.Logger = new LoggerConfiguration()
  .Enrich.WithProperty("Environment", "Production")
  // Other configuration, then...
  .CreateLogger();

When you collect and view these logs with Seq, you might end up writing the filter Environment == "Production" a lot.

Signals-1

Instead of typing this a hundred and twenty times a day, Seq 2 lets you save your filter as a signal. Press the “move to signal” (») button in the filter bar, and one will be created for you:

Signals-2

It’s easy to build up more complex filters by adding them to the signal with ».

The various “exclude” options on event properties and types makes it quick to eliminate noise:

Signals-3

Once you’ve given the signal a name, saved, and closed it, you’ll see it in the signal list ready to activate at the click of a mouse:

Signals-4

(Here’s where Signals in Seq 2 start to shine – to apply multiple signals like “Production” and “Errors”, just click to apply each one, and only events matching all of the applied signals will be displayed.)

Signals are really fundamental to Seq, so busy teams quickly create a lot. To see the list of signals everyone has created, and add them to your own view, use the Create or add signal… link to search the list:

Signals-5

There’s a fresh beta build now available so you can get started with Seq 2. It’d be great to have your feedback as we work through the beta process – please feel free to post here, contact our support address or raise tickets on our issue tracker.

Seq/2 Beta

Last month I posted the first sneak peek of what you can expect from the upcoming Seq “v2″ release.

Since then, the final pieces of the UI have been put (back!) into place, bugs have been squashed, and we’ve incorporated feedback from some helpful early adopters.

Today, though there remains plenty to do, we’re ready to open up the beta to a wider audience. You can now download the latest installer from the Seq homepage.

Timeline

Shown above is the fledgling “Timeline” view, that displays the distribution of matches for any Seq query inline.

What’s inside?

Recapping from the earlier post, the new release is strongly focused on user experience, both by simplifying the UI and underlying model, as well as improving common scenarios and considering the needs of larger projects and teams.

A few of the more noticeable differences:

  • The UI is much more responsive in basic scenarios
  • Queries and views have been combined into a much simpler and more powerful “signal” concept
  • Each user gets their own view of the available signals in the system – signals created by other users can be added explicitly
  • Property and built-in function names are auto-completed in the filter bar
  • Filter syntax help is shown under the filter box when an expression isn’t recognized
  • The interface is much friendlier towards touch devices
  • The dash layout is more compact, getting more info onto the screen in a more useful format
  • Filtering by date and time is easier
  • You can see the distribution of events across a time span without adding a dash item
  • It’s simpler to create a CSV export from all of the currently tagged properties (no more “Properties of Interest”)
  • Oh, and it’s now much easier to select text from log messages

A lot of small bugs and annoyances have been fixed too, and the theme updated to be clearer and more consistent throughout the settings screens.

Installing Seq/2

The goal of the beta release is to get your feedback, and from that angle we’d love you to install it. Here’s what you need to know first.

Stability

The current release is a beta. It’s not perfect – we wouldn’t recommend upgrading critical servers just yet – but it’s usable enough for real-world installations.

Bug reports are greatly appreciated – you can post those on the issue tracker or email us at our support address. Some known issues are listed below as well.

Licenses

As before, Seq/2 comes with a free single-user license that you can use out of the box.

If you’ve purchased Seq in the last twelve months, your license will cover your upgrade to version 2 for free; just go right ahead.

If you have an older license, or just want to try Seq for the first time, you can grab a trial key from the Seq website or contact our support address for help.

Known issues

At the time of writing:

  • The date/time pickers in the timeline view don’t show popup calendars
  • Substantial problems have been reported when using Google Chrome “Canary”
  • Manual event deletion is not available
  • Deep linking into a missing/deleted signal will leave the UI stalled
  • The API client has not been updated to the latest version

What’s next?

We’re hard at work to put the finishing touches on the final version. We plan to post another beta in the next week or two, and at present we’re aiming for a mid-year release.

Thanks for your help – go get it! :-)

Diagnostic logging in DNX/ASP.NET 5

If you’re writing ASP.NET apps with the latest tooling, you will inevitably encounter the Microsoft.Framework.Logging package. It’s a dependency of ASP.NET MVC, WebForms and much of the related infrastructure. “What is this thing?” you ask. Great question!

The Framework writes log events

When an MVC controller is selected, when a static file is served, when an error is caught… ASP.NET and other framework libraries helpfully log this information.

In past .NET versions, System.Diagnostics.Trace was the output of choice, but the world has moved on and the newer package is an alternative with a more modern-feeling API.

What does it look like?

Like ASP.NET 5, your applications and libraries can write events to the framework’s logging pipeline:

var loggerFactory = new LoggerFactory().AddConsole();
var logger = loggerFactory.CreateLogger(typeof(Program).FullName);

logger.LogInformation("Handled in {ExecutionTime} ms", executionTime);

An ILoggerFactory creates ILoggers, and these provide the typical methods you’d expect for logging errors, warnings, debug events and so-on.

You might be surprised (or, you might not!) that just like Serilog, Microsoft.Framework.Logging supports {Named} holes in its format strings, in addition to the typical {0} and {1}. This technique enables structured loggers to provide first-class search operations on not just the raw text of the log message, but the individual property values as well:

Execution Time gt 300 ms

The great thing is that if you’re not using a structured approach, messages will just come through the pipeline as strings – everyone’s looked after.

Microsoft.Framework.Logging vs. Serilog, NLog, SLAB, log4net…

The designers of ASP.NET faced the same dilemma as other library authors in .NET: which logging library should they use to write events? The choice of logger is typically one the application author will make, so frameworks and libraries need a way to support more than one option.

Over time we’ve had a few solutions to this – Common.Logging has been popular, and more recently LibLog does a good of providing a dependency-free API on top of several loggers.

Microsoft.Framework.Logging today is another of these, though it’s somewhat more capable (and in many ways it’s a very nice one).

Although out-of-the-box implementations are provided for basic console logging and a few other targets, you’ll need a logging back-end like Serilog or NLog to gain the kind of functionality expected by non-trivial apps.

So, how does that work?

Getting started

We’ll assume you want to use Serilog. (Instructions for NLog are pretty similar, and an example that uses it can be found here.) The ASP.NET Team wrote the original Serilog back-end for Microsoft.Framework.Logging, and transferred it to the Serilog project where it’s currently supported and maintained.

First, install the Serilog.Framework.Logging NuGet packag into your web or console app.

Next, in your application’s Startup() method, configure Serilog first:

using Serilog;

public class Startup
{
  public Startup(IHostingEnvironment env)
  {
    Log.Logger = new LoggerConfiguration()
#if DNXCORE50
      .WriteTo.TextWriter(Console.Out)
#else
      .WriteTo.Trace()
#endif
      .CreateLogger();
     
    // Other startup code

The conditional compilation (#if) is necessary if you’re targeting the CoreCLR runtime, for which there are currently few Serilog sinks. If you’re targeting the full .NET framework you can just use .WriteTo.Trace(), or any other available sink.

Finally, in your Startup class’s Configure() method, call AddSerilog() on the provided loggerFactory.

  public void Configure(IApplicationBuilder app, IHostingEnvironment env,
                        ILoggerFactory loggerfactory)
  {
      loggerfactory.AddSerilog();

That’s it! With the level bumped up a little you should see log output like:

2015-05-15 22:14:44.646 +10:00 [Debug] RouteCollection.RouteAsync
    Routes:
        Microsoft.AspNet.Mvc.Routing.AttributeRoute
        {controller=Home}/{action=Index}/{id?}
    Handled? True
2015-05-15 22:14:44.647 +10:00 [Debug] RouterMiddleware.Invoke
    Handled? True
2015-05-15 22:14:45.706 +10:00 [Debug] /lib/jquery/jquery.js not modified
2015-05-15 22:14:45.706 +10:00 [Debug] /css/site.css not modified
2015-05-15 22:14:45.741 +10:00 [Debug] Handled. Status code: 304 File: /css/site.css

An important note on levels

If you want to get more or less information from the log you’ll need to change the level.

  • You need to set MinimumLevel on both the Serilog LoggerConfiguration and the ILoggerFactory
  • Serilog and ASP.NET assign different priorities to the Debug and Trace levels; Serilog’s Debug is ASP.NET’s Trace, and vice-versa

Which API should my application use?

Personally, I’m content to let ASP.NET write events with the Microsoft.Framework.Logging API, and to use Serilog’s native API in my application code. The designers of the framework API have gone out of their way to support a wide range of logging styles, so using either is reasonable. I’m obviously somewhat biased, but I prefer the more focused API of Serilog to the more general one from the framework. Your preferences might differ :-).

The important thing is – don’t miss the opportunity posed by ASP.NET 5 to take your logging to the next level and get some structured events through your logging pipeline.

Getting help

If you have questions or comments please feel free to raise an issue on the tracker. We’re also frequently in the Serilog Jabbr chat and happy to help if you get stuck!

Seq/2 Update

When I started building Seq nearly two years ago, I expected it would be used occasionally – after all, chasing bugs in production systems isn’t something we set out to do every day :-)

The first time I visited one of our larger customers on-site, I’d hoped to sneak a glimpse of someone using Seq as I walked through the office. I was in for a bit of a surprise; not only did I spot it running on nearly all developers’ “second” monitors, the QA team had a Seq session open and were collecting up exception information for a bug report when I passed by too!

Watching people use Seq, and using it myself, I’ve come to realize that effective instrumentation begins right up front during development, just like effective testing does. Using your logs during development is the only way to make sure they’re in tip-top shape for the occasional production (mis)adventure, and in the process you can get a much clearer picture of the inner workings of a system.

The net result is that many of us use Seq every day. That puts the bar for usability very high – when you spend a lot of time with an application, ergonomics really matter. Although there are literally thousands of opportunities to expand the product in its next major version, the first priority of Seq/2 is to make the user experience as delightful as it can be.

Seq2PreAlpha

What does ‘delightful’ actually mean? We’ve reviewed and refined nearly every corner of the Seq user interface in the second version. On the events screen, where the “real work” gets done, you’ll find:

  • Queries and views are being merged into a single “signal” concept, which greatly simplifies working with them
  • Combining the filters from multiple signals is as easy as clicking each one to select it
  • Each user maintains their own view of the available signals in the system – signals created by other users are added explicitly
  • It’s easy to create a CSV export from all of the currently tagged properties
  • Property and built-in function names are auto-completed in the filter bar (ooooooh!)
  • Filter syntax help is shown under the filter box when an expression isn’t recognized
  • The interface is much friendlier towards touch devices
  • Date/time range selection is getting a big usability boost
  • Oh, and it’s now much easier to select text from log messages

Of these, we think signals are going to have the most impact; you can already see the simplifications they offer flowing through into the much cleaner (and now full-width!) filter bar. Many other changes are paving the way for exciting things we plan to introduce later in the 2.x series.

Work has been progressing steadily on the new version for several months, and we’re starting to get a better feel for the release date. If all goes smoothly we’ll ship a private alpha to interested users in the next month or so, followed by a public beta nearer the end of June. In the meantime I’m hoping I’ll have a chance to write more about the new version and what else you can expect from Seq this year.

If you’d like to participate in the 2.0 alpha, please sign up for the Seq newsletter via the footer of our homepage; we’ll be continuing to provide monthly updates through that channel. Cheers!

serilog-generator.exe and fun with key-value settings

Some things are just fun to build, and without much concern for its general utility I thought I’d share one of them :-)

serilog-generator.exe is a handy little app for exercising Serilog sinks and log servers without needing a test harness project for each one. It’s published on NuGet as a ‘tools’ package and can be installed into a sink project like any other NuGet package:

Install-Package serilog-generator

(It’s also on Chocolatey but currently fails because of some command-line handling that Chocolatey shims seem to do.)

At a command prompt in a folder containing a Serilog sink assembly, the sink can be loaded, configured, and sample data pushed through it with a command-line like this one that exercises the Seq sink:

serilog-generator --using="Serilog.Sinks.Seq" --write-to:Seq.serverUrl="http://localhost:5341"

Unless --quiet is specified, the log will also be written to the console so you can compare it with what shows up in your sink:

Generator

You might have noticed that the command-line syntax for configuring the sink is very similar to the <appSettings> format supported by Serilog 1.5. Compare the command-line above with:

<appSettings>
  <add key="serilog:using" value="Serilog.Sinks.Seq" />
  <add key="serilog:write-to:Seq.serverUrl" value="http://localhost:5341" />
</appSettings>

The XML version uses a serilog: prefix to disambiguate from other settings often found in config files, but apart from that you can see the basic using/write-to directives (as well as the minimum-level and enrich options not shown here) work the same way.

That’s because the underlying Serilog configuration support is key-value based, not specific to XML settings files. You can read Serilog configuration from any medium that can represent key-value pairs.

Adding a new configuration provider is as easy as finding a way to load the pairs:

var pairs = new Dictionary<string, string>
{
  { "using", "Serilog.Sinks.Seq" },
  { "write-to:Seq.serverUrl", "http://localhost:5341" }
});

Log.Logger = new LoggerConfiguration()
  .ReadFrom.KeyValuePairs(pairs)
  .CreateLogger();

You can see how serilog-generator.exe uses this general support to implement ReadFrom.CommandLine() in its source. There are a couple of subtle points in there but it’s really only a few lines of code.

Reading settings from the command-line might not be particularly useful for many (most!) apps, but if you’re using a different configuration system and want to tap into Serilog’s built-in settings support it can come together quite smoothly.

A Monster Serilog Update for April 2015

Serilog is an open-source logging framework for .NET that seamlessly integrates text-based logging and fully-structured events. You can write events to regular text files, or use Serilog in combination with a structured log server for the easiest log filtering and navigation on the planet!

TL;DR we’ve been busy – Serilog 1.5 is out with new external configuration support; the project has been reorganized; and if you’re in Portland next week you can learn more about Serilog at .NET/FRINGE/.

First up: 1.5 is live!

Serilog 1.4 has been a long-lived and stable release. In fact, well over half of Serilog’s 69,304 downloads have been of the 1.4 series!

Update-Package Serilog

Well – we hope it’s been worth the wait: you can now pick up Serilog 1.5.1 hot off the NuGet press :-)

What’s new? Core support for external configuration sources.

The feature responsible for a minor-version bump is integrated “external settings” support.

Serilog was, is, and always will remain a primarily code-driven library. For a long while however the project offered a simple <appSettings>-based configuration option that could be used to specify the minimum logging level, enriching properties, and sink parameters in XML App.config and Web.config files.

We found this package, Serilog.Extras.AppSettings, popular and useful enough in practice that some support for this functionality in the core is warranted.

If you install the Serilog package into a .NET project with XML configuration support, you can now use the .ReadFrom.AppSettings() method to pull logger configuration directly from an XML configuration file:

var log = new LoggerConfiguration()
  .ReadFrom.AppSettings()
  .WriteTo.ColoredConsole()
  .CreateLogger();

XML configuration is very simple and relies on the <appSettings> element found in standard config files:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <appSettings>
    <add key="serilog:minimum-level" value="Debug" />
    <add key="serilog:write-to:File.path" value="C:\ProgramData\MyApp\my-log.txt" />
    <add key="serilog:enrich:with-property:MachineName" value="%COMPUTERNAME%" />
  </appSettings>
</configuration>

But, we haven’t simply shoehorned the old “extras” package into the core. Serilog’s new configuration support is open and will be fitted to the new ASP.NET 5 configuration system when it’s finalized. There’s already a simple key-value pair setting implementation, .ReadFrom.KeyValuePairs(), that you may find useful if XML isn’t your style.

You can read more about using this feature in the documentation.

New Community Projects

Though the split has been in progress for some time, 1.5 marks the end of a big push from Serilog’s core contributors to break out many of the useful “extras” projects into their own top-level organisations and repositories.

Michiel van Oudheusden led the charge with SerilogMetrics, a Metrics.NET-inspired project that adds timer, gauge, and counter features on top of Serilog. This replaces the original Serilog.Extras.Timing package.

serilog-metrics-256

Destructurama! makes Serilog able to accurately serialize exotic things like F# discriminated unions, or JSON.NET dynamic objects. These packages replace their earlier versions that were contributed and baked as “extras”.

Finally, consistent support for logging web application requests is the goal of the SerilogWeb project. Currently the ASP.NET and OWIN support libraries have moved over, and I have high hopes for these finding some interesting synergy with an ASP.NET 5 integration there when the time comes.

If you’re building something that adds to Serilog, let us know – we’d love to list you on the community projects wiki page we’re maintaining for this purpose.

The Great Sink Split

We’ve bunkered down to make sure Serilog “the project” stays lean and healthy. It’s easy for open source projects that integrate with many technologies to grow and sprawl, and as it evolved Serilog hit nearly fifty interrelated projects in its core solution.

Starting from Serilog 1.5, all of the various provided sinks live in standalone GitHub repositories. Hat tip to Matthew Erbs for helping push this huge task to completion! Combined with the move to establish our new community projects, this brings the Serilog solution itself back to a pair of projects – the portable core, and additional full .NET framework support.

SolutionExplorer

The 1.x series of releases is slowing down, but we’re making sure that we have the right project structure for Serilog to stay fresh and current well into the future.

Who contributed to this release?

We now count 57 individuals on our contributors page. This number isn’t an accurate representation any longer since new (sink) code now lives outside the Serilog repository, so there are even more wonderful folk not listed here.

Anything else?

Yes!!! If you’re lucky enough to have a ticket Daniel Plaisted will be speaking on Serilog at .NET/FRINGE/ next Monday, 13th April in Portland, OR.

DotNetFringe

The conference is about breaking the rules and pushing the boundaries of .NET, so I’m especially excited to hear Daniel will be presenting Serilog there.

Serilog 1.5 is now on NuGet, go get it!

C# 6 string interpolation and Serilog

It’s easy to spot the similarity between Serilog message templates:

// Serilog
var loggedInUserId = "nblumhardt";
Log.Information("Logged in {UserId}", loggedInUserId);

and C# 6 interpolated strings:

// C# 6
Log.Information($"Logged in {loggedInUserId}");

This is naturally because of their shared common ancestor, the .NET format string. Under the hood, interpolated strings in C# are converted by the compiler into a struct with the classic format string and argument values, logically along the lines of:

// C# 6 desugared
Log.Information(new FormattableString
  {
    Format = "Logged in {0}",
    Args = new object[] { loggedInUserId }
  });

The similarity has led a few of us, since seeing the new C# feature, to wonder whether a few keystrokes might be shaved off of the Serilog API if only the C# compiler would preserve the names of the “holes” in the interpolated string, i.e. loggedInUserId in this example.

There was initially mention of Serilog on the design thread for the feature, and more recently Andrey Shchekin most graciously raised a ticket on the Roslyn issue tracker as a prompt for some support in C# 7.

I’ve had some time to think about this feature now, and while the concision is appealing, I’m no longer convinced string interpolation (name preservation or not) is a good fit for Serilog.

1. A good variable name is not necessarily a good property name

Let’s take the example above; in our hypothetical C# 6 example the complete snippet would look like:

var loggedInUserId = "nblumhardt";
Log.Information($"Logged in {loggedInUserId}");

The variable name loggedInUserId obviously reflects what this value is being used for by the program. But, if that name was carried through to the log event, e.g.:

{ { "Properties": { "loggedInUserId": "nblumhardt",

This would lead us to query the log with filters like:

loggedInUserId == "nblumhardt"

Fine if we only want to find events where the user was logged in, but in the context of a larger and more complex application, we’ll often want to find as many events as possible that are related to a specific user (who might be having some technical trouble!).

In that case, a more general property name is a better fit:

Log.Information("Logged in {UserId}", loggedInUserId);

// Elsewhere
Log.Information("Password for {UserId} successfully changed", loggedInUserId);

This small change allows us to query UserId == "nblumhardt" and find both matching events.

Log event property names are important enough for diagnostics that they deserve their own identity, separate from the variable names around them.

2. Holes don’t always have obvious names

What does the property name for this statement look like?

Log.Information($"Enabling categories {new[]{1, 2, 3}}");

Here the hole is filled with an expression that’s not a simple name, so some kind of munging would be necessary in order to turn it into a valid log event property name (a JSON identifier or similar).

Going down this path would definitely reduce the overall quality of log events, and elevating log events to first-class status is what Serilog’s all about.

So what’s the relationship between Serilog and C# 6, then?

String interpolation is a great feature, one I’ve looked forward to in C# for a long time. The idea of providing direct support for Serilog is a very interesting one and worth exploring, but I’m increasingly convinced it’s unnecessary.

Interpolation is nice when it keeps code DRY, cutting out the redundant clutter of {0} and {1} and preventing parameter mismatches.

In the case of Serilog, I think it’s incorrect to consider the property names like {UserId} as redundant; in a well-implemented logging strategy they’re an incredibly important part of the picture that deserve their own consideration. You wouldn’t let variable names determine the table and column names in a relational database – it’s exactly the same trade-off being considered here.

What do you think? I’d love to be convinced there’s more synergy to be found here, but I’m not seeing it at present.

Tagging log events for effective correlation

Correlation, at least when we’re talking diagnostic logs, is the process of finding events that are related to each other in some way. It’s typical to correlate events raised during a transaction, on a specific thread, on a machine or from steps in some kind of process.

Correlation is king in the world of operating complex, distributed and asynchronous apps: it’s how the signal is picked out of the noise – the wheat from the irrelevant chaff – the diamonds that will help you solve a critical issue from the mud of day-to-day happenings.

I gave a presentation a few weeks back at DDD Brisbane on building better apps by taking an active approach to logging. The last post should give you an idea of the flavor of it. After the talk some nice folks approached me and said I’d filled in a missing link for them – it made me realize I’ve been using a little strategy for correlation without really thinking about it, and you might find this useful too.

Contextual correlation

For a long time, diagnostic logs have incorporated contextual information into events. Context tells you what was happening when an event was raised, or where the event was raised from. In its earliest form it might be the thread ID you sometimes see formatted into text logs:

2015-01-22 10:55:05.776 INFO [22] Serving catalog index
2015-01-22 10:55:05.902 WARN [8] Query took 109 ms
2015-01-22 10:55:05.902 INFO [22] Responding with OK

The thread ID in this case is included in each log message between brackets after the level. It tells us that the warning on the second line was raised on thread 8, which isn’t the same thread as was concurrently serving the product catalog (thread 22), so the source of the warning was elsewhere.

Searching a simple text log like this we could grep for /[8]/ to see what else was happening on thread 8 and hopefully narrow down on the source of the slow query.

Serilog does contextual correlation in a few different ways.

Enrichers can be used to attach different contextual properties to events:

var log = new LoggerConfiguration()
  .Enrich.With<ThreadIdEnricher>()
   // Other config here, then…
  .CreateLogger();

Enrichers work well when the context of an event can be determined statically – i.e. it’s something ambient like the thread id, machine name, the logged-in user, and so-on.

For context that’s more localized, there’s a special enricher that can be added to enable the Log Context:

  .Enrich.FromLogContext()

Once the log context is enabled, a block of related messages can be tagged using the methods on the LogContext class:

using (LogContext.PushProperty("MessageId", GetCurrentMessageId()))
{
  Log.Information("Processing {OrderId}", message.Order.Id);

  // Later
  Log.Information("Order processing complete");
}

If we look at these logs in Seq, we’ll see an MessageId property attached to each event within the using block:

1-MessageId

This can be used as a filter, e.g. MessageId == 12345, to view the events raised when processing the message.

Contextual correlation is bread-and-butter stuff. If your application processes work asynchronously, you need to be able to filter down to a single task, and properties tagging events from a context make this as painless as possible.

It’s worth noting that contexts overlap – an event can belong to a thread as well as to a message. (This is one of the arguments for structured logs – it’s much easier to work with events with real, named properties than it is to devise readable, unambiguous ways to embed all of these into the format of a text log message.)

Setting up and using the log context does add some noise to application code, so it’s something to be used judiciously. To tag events for correlation without additional machinery, another technique is useful.

Lateral correlation

If you think about all the contexts in your running application, you might come up with a mental picture like this:

Contextual

The green lines show sequences of events tagged with the same RequestId property, while blue shows a MessageId property that might be added to events during back-end processing. There’s some simplification here, given the way contexts overlap, but essentially each context is a temporal sequence of correlated events.

When it comes time to use these logs however, scenarios frequently cross these little islands of navigability, so something else is needed.

Let’s say we’ve received an issue report tagged with an exception message. We find the exception using the text:

2-InvOrder

And then follow the MessageId contextual property to see what happened in the message handler that failed.

3-Mid

Now, we know somehow we were sent an order without any items – where did it come from? This is where a lateral correlation identifier comes in handy. The second event in the three above implements this:

Log.Information("Processing {OrderId}", message.Order.Id);

OrderId is a business-domain identifier included in the message itself that links the event across lines of causality to others related to the same order.

Once we jump across contexts using the OrderId:

4-Find

We can now see an event from the HTTP request that initiated the order.

5-Req

(A keen-eyed reader might note here that searching on ItemCount == 0 would have narrowed things down a little faster – but identifying this opportunity still requires some navigation through the logs from the point of failure too.)

Correlating by HTTP request Id we get all of the events from the request and should (on a real event stream) be able to get to the bottom of the issue:

6-Final

Patching this into our mental model, OrderId let us navigate laterally between the two sequences of events.

Lateral

Logging in two dimensions

Armed with a tool like structured logging that can easily be overused and create clutter, the last thing anyone wants to do is bung every possible property onto every event in an attempt ease diagnostics later on.

Keeping a clear distinction between the contextual and lateral correlation links makes it possible to navigate effectively through events raised by the app with a minimum of syntactic noise.

It turns out that in most situations I’ve encountered, architectural and infrastructural concerns dominate the notion of context. HTTP request id, thread id, message id – these are all mechanical concerns that get buried into plumbing and attached using enrichers or the log context. This is pretty convenient – the noisier APIs for adding contextual properties are best kept in infrastructural code when possible.

Identifiers from the business domain provide lateral navigation through logs – customer ids, order ids and the like – letting you skip between the various contexts in which an entity was referenced. Using structured logging these links can be created without much fanfare – just logging an event with the identifier in its message text is enough to make the connection.

It’s a simple perspective that helps me use structured logs more effectively, and it can be a nice foundation for guidelines shared with a team. If you use this strategy already, or another similar one, I’d love to hear more about your experiences!