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.

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!