Posts by Nicholas Blumhardt

Seq 2.4

Hot off the press and ready to download from the Seq site.

Seq 2.4 is largely a maintenance release with a host of bug fixes, but amongst those are some substantial improvements.

Filtering performance improvements

Seq implements its own query engine (soon to get some interesting new capabilities ;-)) optimized for the kind of messy, ad-hoc filtering that we do over log data. Based on the kinds of queries generated through real-world use of the 2.0 “signals” feature, two great little optimizations have landed in 2.4.

First, an overdue implementation of short-circuiting && (AND) and || (OR). This just means that the expression @Level == "Error" && Environment == "UAT" won’t bother evaluating the second comparison if the first one is false. Seq has always done some short-circuiting in queries, but only in certain cases. 2.4 extends this to all logical operations.

Second, and closely related, is term reordering based on expected execution cost. Some predicates are extremely cheap and others costly, for example an event type comparison ($FEE7C01D) can be evaluated several thousand times faster than a full-document text search (Contains(@Document, "penguin"). This means that, given short-circuiting operations, $FEE7C01D && Contains(@Document, "penguin") is much more efficient than the reverse Contains(@Document, "penguin") && $FEE7C01D in the common case of mostly-negative results. Seq 2.4 uses heuristics to weigh up the relative execution cost of each branch of an expression to make sure the fastest comparisons are performed first.

Both of these changes add up to substantial gains when using signals with a large number of applied filters.

Restricted signals

Since Seq uses the signal mechanism for retention processing, it’s possible that an accidental change to a signal used in retention processing could lead to data loss. For this reason Seq 2.4 introduces lockable signals, requiring administrative privileges to modify.

Seq-2.4

Online compaction

Seq uses the ESENT storage engine to manage files on disk. It’s an amazing piece of technology and very mature, however until recently was unable to support compaction of data files during operation. Although retention policies would remove events from the file, Seq would periodically need to take a slice of the event stream offline to free the empty space in the file, and this process copies the old file into a new one. Mostly this background operation would be quick and transparent, but on heavily loaded servers the disk space and I/O required would sometimes significantly impact performance.

The new version 2.4, when running on a capable operating system (Windows 8.1+ or Server 2012 R2+), now takes advantage of ESENT’s sparse file support to perform compaction in real time, spreading out the load and avoiding additional disk usage and I/O spikes.

You can download the new version here on the Seq website.

Happy logging! :-)

Assigning event types to Serilog events

One of the most powerful benefits of structured logging is the ability to treat log events as though “typed”, so that events generated by the same logging statement can be easily (and mechanically) identified in the log stream.

Given a logging statement parameterized by some data:

var total = 1;
for(var i = 0; i < 3; ++i)
{
   total *= i;
   Log.Information("Computed iteration {Counter}, total is {Total}", i, total);
}

The text representation of each event (“Computed iteration 2, total is 4”) will be different.

A traditional text-based logging system necessitates the use of regular expressions to identify and parse messages created in the loop. This is a bigger problem than it sounds: once the event is interspersed through a large stream of unrelated messages this style of processing is both slow and error-prone, as well as inconvenient.

By contrast, a structured logger like Serilog or SLAB/ETW assigns ids or types to events, so that all events generated by the statement will carry a distinct type as well as the structured fields for Counter and Total. Queries using event types can find all of the events generated by a particular logging statement, even though their text representations may differ.

Enriching events with types

Serilog treats the message template itself as the event type. By attaching "Computed iteration {Counter}, total is {Total}" to each event, all events generated from the same template can be identified.

Long strings like this can be inconvenient to record and type, so it’s often useful to take a hash of this value instead, and record that as the event type alongside other data comprising the event. Seq does this automatically by assigning a type to Serilog events on the server-side. Using Elasticsearch to store events, you might achieve the same thing with a transform.

If you just want to have the convenience of searching by event type in regular flat log files, or if you’re using a log collector without this option, it’s easy to add support for it using a Serilog enricher:

Log.Logger = new LoggerConfiguration()
   .Enrich.With<EventTypeEnricher>()
   .WriteTo.LiterateConsole(
      outputTemplate: "{Timestamp:HH:mm:ss} [{EventType:x8} {Level}] {Message}{NewLine}{Exception}")
   .CreateLogger();

Line 2 adds the EventTypeEnricher that we’ll see below to the logging pipeline.

Line 3 shows the modified outputTemplate that includes the EventType value, in this case a 32-bit value formatted in hexadecimal. (This example writes to the Literate Console sink, which is a great way to visualize the structure of Serilog events even when they’re formatted into text.)

The enricher

In this example, event types are generated using a 32-bit Murmur3 hash. The relative merits of different hash algorithms and sizes for this purpose is a post in itself – we’ll just use a readily-available one. Anything from string.GetHashCode() to SHA-1 might work here, depending on your needs.

The algorithim is from this package, which you’ll need to install first from NuGet.

class EventTypeEnricher : ILogEventEnricher
{
   public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
   {
      var murmur = MurmurHash.Create32();
      var bytes = Encoding.UTF8.GetBytes(logEvent.MessageTemplate.Text);
      var hash = murmur.ComputeHash(bytes);
      var numericHash = BitConverter.ToUInt32(hash, 0);
      var eventId = propertyFactory.CreateProperty("EventType", numericHash);
      logEvent.AddPropertyIfAbsent(eventId);
   }
}

The enricher retrieves the original message template text, computes its hash, and attaches it the event as the EventType property.

The output

Taking our example again, including a few different events:

Log.Information("Starting up");

var total = 1;
for (var i = 0; i < 3; ++i)
{
    total += i;
    Log.Information("Computed iteration {Counter}, total is {Total}", i, total);
}

Log.Information("All done");

The output is:

EventTypesLiterateConsole

Each loop of the iteration, despite carrying different values for Counter and Total, is tagged with the same event type f20ba6e0. The other two events carry their own distinct event types that identify them.

Summing up

Structured logging is a necessary response to the difficulty of sifting through log events from ever-larger, more distributed, more sophisticated applications. Alongside named property values, event types are a big part of the structured logging value proposition. You can use either raw message templates, or hashes of them, as types when working with Serilog.

If you’re using a solution that supports event types in your log data, it’d be awesome to hear how it has worked for you!

Server Efficiency and “Seq App” Input Changes in Seq 2.3

Apps are Seq extensions that drive notifications like email and Slack, stream processing, and Seq’s inbuilt dashboard charts.

In earlier versions, apps used a persistent cursor into the event stream and a short buffering window to track delivery and sort incoming events by timestamp. This implementation was based on the assumption that many apps would want loosely-ordered input, and providing this in the server rather than each app individually would be most efficient.

The flipside of this decision was that ordered delivery and a persistent cursor for each app still required quite substantial resources. Seq servers with many dashboard charts or running apps could spend a large amount of CPU and I/O time updating them. This turned out to be largely a waste, given the infrequent need for ordering, and the limited benefits of a persistent cursor when the event delivery process is inherently unreliable.

Seq 2.3 gains some big performance wins by using in-memory delivery of incoming events to apps. The overhead of running apps in this mode is negligible, so the difference can be noticeable. A loaded test server running just five charts used close to 70% less CPU time on 2.3 than on 2.2.

Because most apps benefit from the new model, this is the default on 2.3 servers. Apps that might behave differently with this change can opt back into ordered delivery using a new setting Order events by timestamp.

Order-by-timestamp

Hopefully the new version will make your server smile! :-)

Set the asterisk in project.json version numbers

I have a feeling I’ve bothered the friendly people on Jabbr twice now about how to set a value for the * (‘wildcard’) placeholder in DNX’s project.json files, so here it is for next time… :-)

DNX project.json files use a version syntax that makes it easy to set a tag (e.g. the branch name) in the JSON file itself, while adding a unique numeric suffix at build time.

Here’s one in the first property below:

{
    "version": "1.0.0-beta-*",
    "description": "Serilog provider for Microsoft.Framework.Logging",

(I’m setting up CI for a Serilog provider for Microsoft.Framework.Logging that the ASP.NET team put together and contributed to the project.)

These work both in the package’s own version field, and in dependency versions, so multiple projects being built at the same time can depend on each other this way.

However, if you build a project versioned this way in Visual Studio, or at the command line with dnu build you’ll get a version number like 1.0.0-beta. That’s not what you’re after.

The key is setting the DNX_BUILD_VERSION environment variable, e.g. to a counter supplied by your build server:

set DNX_BUILD_VERSION=%APPVEYOR_BUILD_NUMBER%

With this done you’ll get nice unique package versions like 1.0.0-beta-234.

Thanks David Fowler and Alex Koeplinger for the pointer.

Seq 2.2: Memory Efficiency, One-click Auto-refresh, Filter History

It took some restraint to get Seq 2.0 over the line: there are so many possibilities that there’s really no way everything I’d like to have done could make the cut. Now the “big bang” is over, it’s great to be able to make more regular point releases like Seq 2.2, which this post is about.

Improved Memory Efficiency

Seq is a disk-backed data store that uses memory caching extensively. When data from older events does spill over from RAM, I/O is needed and queries slow down.

Seq 2.2 performs additional de-duplication of string data to represent more events in the same cache space. This reduces the need for I/O and places less overall burden on the CPU. The net effect is that queries can run noticeably faster on busy servers.

One-click “Auto-refresh on”

The much-used “Auto-refresh on” option has been promoted from a drop-down menu item to a top-level button. It’s represented by the little “infinity” icon in the image above.

AutorefreshButton

Recent Filter History

Seq 1.6 used deep-linking to tie the current filter expression to the web browser’s history. The basic idea was sound – it’s nice to enter a filter, try another, then press “Back” to go to the previous one.

In practice log navigation is so fluid that what you thought was the last filter often turns out to be a few clicks back, which ends up being a clunky back-back-back experience. Seq 2.0 therefore booted out back button support for filters, instead providing coarse-grained history between the dash, settings, and events screens (deep-linking of filters is still supported, but they don’t go on the browser’s back-stack).

Seq 2.2 brings back the notion of history in the guise of a “recent filters” drop-down you can see in the right of the filter box. Clicking on one of the history entries will set the filter to that text:

History

The release includes other small enhancements and bug fixes, listed in the complete release notes.

There will be more point releases in the 2.x cycle at about the same 2-4 week interval, but 2.2 really is one not to miss. You can download it now from the Seq website — let us know what you think!

Contextual logger injection for Autofac

TL;DR: install package AutofacSerilogIntegration, call builder.RegisterLogger(), and use constructor injection of ILogger to get source type tagging.

When I use Serilog, I more often than not embrace the static Log class and use a pattern like:

class Example
{
    readonly ILogger _log = Log.ForContext<Example>();

    public void Show()
    {
        _log.Information("Hello!");
    }
}

Notice in this example the ForContext<Example>() call. This creates a contextual logger that will tag all of the events created through it with the name of the specified class, in this case Example. Serilog does this by attaching a property called SourceContext.

SourceContext can be very useful for filtering. Here, using the Seq sink, we can see all events raised by PreadmissionController:

SourceContext

Logger Injection

When using an IoC container like Autofac, it’s quite common to inject a logger into the class using it. In this case our example would follow a slightly different pattern:

class Example
{
    readonly ILogger _log;

    public Example(ILogger log)
    {
        _log = log;
    }

    public void Show()
    {
        _log.Information("Hello!");
    }
}

Here, instead of calling ForContext<Example>(), the expectation is that the appropriate logger will be passed into the constructor by the caller.

Though I’ve tended to move away from this pattern in recent years (if for nothing else, just to cut down the number of parameters on constructors!) I’ve encountered lots of codebases that use this tactic and find it works well.

Unfortunately, despite founding both the Autofac and Serilog projects, when asked how to set this up I’ve had to point people to Google and newsgroup posts, and don’t think there’s been a comprehensive example online showing how it can work efficiently and reliably. So, finally, I’ve posted a working integration on GitHub and published it as the AutofacSerilogIntegration NuGet package. Here’s how it’s used.

Setting up the Autofac/Serilog Integration

As with all good stories, this one begins at the NuGet package manager command-line:

Install-Package AutofacSerilogIntegration

(This assumes you’ve installed both the Autofac and Serilog packages already.)

The first thing you should do in your application is configure a logger. I recommend assigning this to Log.Logger even if you don’t intend to use the static Log class, just in case any calls to the static logger slip in accidentally.

Log.Logger = new LoggerConfiguration()
    .WriteTo.ColoredConsole()
    .CreateLogger();

Next up, where your Autofac ContainerBuilder is configured, call RegisterLogger(). This is an extension method in the AutofacSerilogIntegration namespace..

var builder = new ContainerBuilder();
builder.RegisterLogger();

And, that’s everything. For components created by the container, parameters of type ILogger will now be fulfilled using a logger instance tagged with the correct type.

The RegisterLogger() method accepts a couple of parameters – an ILogger can be specified if you want to use a root logger separate from the static one, and property injection can be optionally enabled.

Closing thoughts…

This is a shiny new slice of code and there may still be scenarios it doesn’t handle so well. The beauty of getting it to GitHub is that over time it can be improved through use – pull requests appreciated! I hope it saves you some searching next time you hit File > New Project.

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 :-)

Contender for .NET’s Prettiest Console?

Working on the UI for Seq 2 involved a lot of time at the command line with Node.js-based tools like npm, Gulp and Mocha, and the output from these is great. There’s heaps of love put into great formatted and colored output in the Node.js ecosystem, and switching back to .NET on the server left me with console envy…!

A few months back I decided to take matters into my own hands and see how Serilog’s trusty old colored console output could be improved upon. The result was the Literate Console sink, it’s now become my go-to option for command line apps.

Here are a few typical Serilog events:

Log.Debug("Starting up on {MachineName} at {WorkingSet} bytes", machineName, workingSet);
Log.Information("Hello, {Name}!", userName);
Log.Information("Recieved order {@Order}", new { Item = "Dessert", Quantity = 3, IsReady = true });
Log.Error(ex, "Could not divide {Numerator} by {Denominator}", numerator, denominator);

And here’s how they’re rendered by the Literate Console sink:

Literate

If you look closely, you’ll see that in fact all of the properties are colored according to type: strings are cyan, numbers magenta, Booleans blue and other miscellany get a fetching green.

Hence the name: Literate Programming intersperses readable text with chunks of executable code; Literate Logging (okay, I confess I just made that up) intersperses the text with chunks of structured data.

You can WriteTo.LiterateConsole() by installing the Serilog.Sinks.Literate NuGet package. Enjoy!

(Know a .NET project with great console output? I’d love to check it out – let’s hear about it! :-))

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.