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!

Using Serilog with F# Discriminated Unions

Serilog

This week GitHub user vlaci called us out on awful F# support in Serilog. In their issue report they show how a nice clean discriminated union type like “Option” is represented hideously in structured data:

type Shape =
    | Circle of Radius : double
    | Rectangle of Width : double *  Height : double
    | Arc // ...
let shape = Circle 5.
Log.Information("Drawing a {@Shape}", shape)

Prints:

2015-01-14 16:52:06 [Information] Drawing a Circle { Radius: 5, Tag: 0, IsCircle:
   True, IsRectangle: False, IsArc: False }

The verbosity gets worse for types with more values.

I took this as a chance to crank up Visual Studio and get reacquainted with F#, using the example from @vlaci as a starting point. Using Serilog.Extras.FSharp you can now enjoy your discriminated unions encoded pleasantly like:

2015-01-14 16:58:31 [Information] Drawing a Circle { Radius: 5 }

Depending on the log storage you use you’ll be able to query on the tag as well as the fields (like Radius) from the union.

You can enable this by installing the package and adding Destructure.FSharpTypes() to your logger configuration:

open Serilog

[<EntryPoint>]
let main argv =

    Log.Logger <- LoggerConfiguration()
        .Destructure.FSharpTypes()
        .WriteTo.ColoredConsole()
        .CreateLogger()

    Log.Information("Drawing a {@Shape}", Circle 5.)

    0

Thanks again to vlaci for kicking this off. I was especially keen to see this in because I’m sure someone with better F# skills than mine can add a lot to the Serilog/F# experience. If you have ideas we’d love to hear from you on the project site!

Querying collection properties in Seq 1.5

Seq implements a filtering syntax that’s loosely based on C#. The following expression matches the events you’d expect it to, if you’re used to working with C# or a similar language:

Tag == "seq"

Which is to say: “Match events where the Tag property has the value "seq". Sub-properties of objects can be accessed using the familiar dotted syntax (Property.Subproperty.Subproperty) and so-on.

Seq 1.5, currently a preview, steps into some new territory.

What about a collection of tags?

It’s not uncommon for Serilog events to carry properties that are collections. For example we might log events on a Q&A site like:

Log.Information("User {Username} posted a question tagged {Tags}", username, tags);

Resulting in events like:

Event with Collection Property

Instead of being marked with a single tag, each event carries a collection of zero-or-more.

Matt Hamilton asks:

This is where Seq 1.4 draws a blank. Translating this to the Q&A example, about the best we can manage is a text search for "seq" and requiring the existence of the Tags property using Has(Tags).

This is a bit of a shame – the promise of Seq and structured logging in general is to make querying log events precise – so why aren’t collections covered?

The C# way

Seq isn’t only about precise queries; the whole foundation of the app is the idea that it should also be easy and natural to query log data.

I’d thought about collection queries quite a lot when putting the original filtering syntax together. C#-style the query would look something like:

Any(Tags, tag => tag == "seq")

Seq doesn’t use extension method-style calls, but this is pretty close to the Enumerable.Any() call you’d write using Linq.

I don’t like it!

In a full-featured programming language this syntax makes sense, but it’s too noisy, complex, and easy to mistype to make a good filtering syntax for Seq. And so, that’s where things have sat for the last twelve months.

Pattern matching

With a bit more thought, Matt and I both ended up thinking the problem might be better suited to a pattern-matching syntax like:

Tags[?] == "seq"

So, this is what Seq 1.5 provides. The question mark wildcard ? matches any element in the collection, while an asterisk * wildcard only matches if all elements satisfy the condition.

Questions tagged seq

Wildcards work in any comparison where one side is a property path (including indexers and dotted sub-properties). Multiple wildcards along the path are supported.

You can write the following expression to find questions where all answers are "Yes!":

Answers[*].Content == "Yes!"

(Under the hood, Seq rewrites these expressions into the equivalent lambda-style syntax – much the same way as the C# compiler transforms Linq query comprehensions. Working through implementing this reminded me just how fantastic the C# compiler really is!)

Try it out!

You can download a preview build of Seq 1.5 here. It’s not ready for production use yet, but should be just fine for dev/non-mission-critical servers. We’d love to hear what you think!

Can we change the face of JavaScript logging, too?

If you use Serilog in .NET and write code for the web, chances are you’ve wondered whether similar hybrid “structured/text” loggers exist for the browser and Node.js

serilog-js

If you haven’t tried Serilog, here’s a one-minute primer (using JavaScript syntax) so you can follow the rest of this post. Using Serilog is similar to every logging framework, ever:

var name = "Nick";
var wait = 45;
log("Hi {name}, your flight leaves in {wait} minutes", name, wait);

Look carefully at the string formatting though – particularly the way we give names to each of the parameters. The “message” part isn’t destructively rendered into text, but preserved as an object with property values. It can be formatted to the console etc. as usual:

[inf] Hi Nick, your flight leaves in 45 minutes

But more interestingly, it can be serialized in a format like JSON for processing and querying:

{
  "message": "Hi Nick, your flight leaves in 45 minutes",
  "messageTemplate": "Hi {name}, your flight leaves in {wait} minutes",
  "properties":  {
    "name": "Nick",
    "wait": 45
  }
}

Preserving the structure of log data, and making it trivially easy to enrich that data with more contextual information, makes it possible to do some really clever things with the resulting logs.

Try finding all messages where the user’s name starts with “N”, or where the wait time is greater than one hour in a traditional log file if you’re skeptical here. In some trivial cases a regular expression might handle this cleanly, but it quickly becomes complex and cumbersome when more data is involved. Using Serilog it can be as simple as startswith(name, "N") or wait > 60.

Preserving the message template itself ("Hi, {name}...") also has some interesting and very useful results: the message template becomes a kind of “message type” that can be used to find – or exclude – messages of a specific type. Again very hard, often impossible with traditional loggers.

What’s going on in JavaScript?

In JavaScript as elsewhere, there are already some sophisticated logging frameworks, with varied levels of structured data support. A fairly new project called node-bunyan interests me the most, with its clever DTRACE integration and support for serializing objects instead of messages, but even here the new hybrid-style API and DSL provided by Serilog is missing. With node-bunyan it’s possible to log an object and/or a message, but messages are still formatted out in a lossy manner like the earlier loggers on .NET did.

Whether it grows into a standalone project in its own right, or encourages more established frameworks to take a look at this new style of logging, bringing Serilog’s API to JavaScript seems like a fun and worthwhile thing to try.

serilog.js

Tinkering away over a month of so I’ve sketched out what I think serilog.js should look like.

serilog.js-example

Yes, serilog.js terminal output is type-aware, just like syntax highlighting in an IDE! It’s useful when dealing with structured events to see the difference between a number 5 (magenta for numbers) and a string "5" (cyan for strings). In itself this feature is a nice trimming, but it’s not just a party-trick; below the surface, the event is carrying all of this information.

Getting started – installing from NPM

All the code is currently published to NPM. At the command line:

npm install serilog

Then in your node application:

var serilog = require('serilog');
var terminal = require('serilog/src/serilog-terminal-sink');
var file = require('serilog/src/serilog-file-sink');

Serilog “sinks” are destinations for log events. This example uses the terminal sink, which writes to the system terminal/console. At the moment, the sinks are all zipped up directly in the serilog package, but they need to be split out.

Tour of the API

At present, with very little of the back end ‘sinks’ built, serilog.js is all about the API.

Configuring the pipeline

One of the first things to notice is that the logger is a pipeline. Thinking of log events as structured data leads naturally to an API more like what you’d find in event processing frameworks than the typical logging library.

var log = serilog.configuration()
  .writeTo(terminal())
  .minimumLevel('WARNING')
  .writeTo(file({path: 'log.txt'}))
  .createLogger();

Each element is applied in turn:

  • serilog.configuration() kicks things off by creating a new configuration object
  • .writeTo(terminal()) emits all events to the terminal sink
  • .minimumLevel('WARNING') filters out any that are below the WARNING level (we’ll cover levels below)
  • .writeTo(file({path: 'log.txt'}) emits the events that reach it to a log file, and
  • .createLogger() takes all of these pipeline stages and bundles them up into an efficient logger object

The result is log, which we’ll use below. (As in Serilog for .NET, there’s no “global” logger – multiple loggers can be created and are completely independent, unless you link them together with something like .writeTo(log2)).

You might be wondering – why not Node.js streams or RxJS etc.? Simple really – generic APIs are great for glueing together solutions, but for something that’s used extensively in a codebase, maintaining complete control over dependencies, performance and semantics is a good idea long-term, and that’s the path taken here.

Logging levels

serilog.js has four simple logging levels, listed here in order of importance:

log.trace('This is a lot of detail');
log.information('Something of note happened');
log.warning('Look out, wheels are coming off!');
log.error('Something's broken');

If log.information() looks like a bit of a mouthful, don’t worry: the log object itself is a function that can be called as a synonym for information:

log('This is an information-level event');

The default level for a new logger is INFORMATION; using .minimumLevel('TRACE') at the start of the pipeline will bump this up.

Message templates

The syntax of message templates is carried over directly from Serilog. Event properties are named by including them in braces, and the values are provided as positional arguments:

log('{a} + {b} = {c}', 1, 2, 3);
// -> {properties: {a: 1, b: 2, c: 3}}

I’ve left the message/template/timestamp out of the example output (// -> ...) to keep the focus on the structured part of the event, but these other parts of the event exist too.

If you pass an object to the log, e.g.:

var mail = {to: 'nblumhardt', subject: 'Is the post finished?'};
log('Sending {mail}', mail);
// -> {properties: {mail: '[Object] object'}}

You might be surprised that it’s stored using toString(). We haven’t missed a great opportunity to serialize here – the problem is that it is very easy to serialize too much data by mistake this way.

If you know that what you’re passing into a log method is a nice little chunk of data to work with later, prefix the property name with @ to say “I know what I’m doing – serialize this!”:

var mail = {to: 'nblumhardt', subject: 'Is the post finished?'};
log('Sending {@mail}', mail);
// -> {properties: {mail: {to: 'nblumhardt', subject: 'Is the post finished?'}}}

serilog.js can handle structured storage of objects and arrays nicely, and these can support some really cool processing scenarios – just don’t forget the @ (if you watch the events roll by on the terminal, you’ll notice the difference too – objects are colored green, while strings render in cyan).

Context and enrichment

The strength of structured logs is in correlation; this is one of the great challenges when instrumenting distributed apps, and probably the #1 reason that interest in structured logs has picked up again in recent times.

When searching a large number of events produced across many machines, it’s vital to have properties to filter on so that a single location or thread of interaction can be followed.

In a simple case, you might want to instrument all events with the name of the machine producing them. This can be done when configuring the logger:

var log = serilog.configuration()
  .enrich({machine: env.HOSTNAME})
  ...

Events created by the logger will all carry the specified properties:

log('Hello, {name}', 'Nick');
// -> {properties: {name: 'Nick', machine: 'NBLUMHARDT-RMBP'}}

More often though, it’s desirable to tag events produced within a part of the application, or in a transaction. For this the using() method is provided on the logger itself:

var smtpLog = log.using({subsystem: 'SMTP'});
smtpLog('About to send mail to {name}', 'Nick');
// -> { properties: {subsystem: 'SMTP', name: 'Nick'}}
Filtering

A final part of the API to check out is filtering. While most filtering will happen server-side wherever you collect your logs, it can be useful to apply some filters in the logging pipeline if you have a component producing a lot of noise, or if you need to avoid passing events with sensitive data to logs.

This fits in as you’d expect:

var log = serilog.configuration()
  .filter(function(evt){
    return evt.messageTemplate.raw !== 'Making {noise}' &&
      evt.properties.subsystem !== 'SMTP';
  })
  .writeTo(terminal())
Building serilog.js

If you want to tinker with the project, you can grab the source from GitHub. The build process uses gulp to drive some mocha tests. Just type:

npm install
gulp

…and you’re away!

The browser

serilog.js also runs in the browser (though version support will be patchy and is completely untested!). There are some notes on the GitHub site linked above on how to do this, and a test.html page in the repository that sets some of it up.

The catch

Serilog in .NET is out there in production use today. It’s being extended and refined by a core group of contributors and takes what time I have available to coordinate.

I’ll be using serilog.js in a few small JavaScript projects and extending it for my own needs, and I’ll be building a sink that writes to Seq at some point. But, I don’t have the capacity to really drive this project beyond the prototype that it is right now.

If you’re interested in JavaScript, event processing, application monitoring and/or API design, serilog.js needs you. Kick the tyres, check out the code, send a pull request! It’s a project “up for grabs” in the largest sense. Can you help change the face of JavaScript logging?

Seq 1.4 preview is out!

The features planned for Seq 1.4 are starting to come together. There’s a new preview available to download on the Seq website (direct download).

While 1.4 is still a little way off “done”, many of the improvements we’ve made are usable today; here’s a run through what you can expect from the new version.

What’s Seq? Seq is the fastest way for .NET teams to improve visibility using structured application logs. If you’re using Serilog, you’ll find Seq is the perfect partner – trivially easy to set up, and built for structured log events so querying them is simple from “day 1” of a project. You already use CI and automated deployment: Seq is the next piece of the puzzle, closing the loop to show your team what’s happening in development, testing and production.

Charts

New in 1.4:

Counters-Downloads

Charts show the count of matching events in a time period. You can view the last day (by hour), last week (by day), last month (by day) or last year (by week). It’s a simple feature that I’m sure we’ll expand on, but already a great way to keep a “finger on the pulse”.

To add a chart, filter the “events” view to show just what you want to chart, then drop down the “refresh” button and select “Add to dash”. By default, queries are shown on the dash as counters; to toggle between the counter and chart display, there’s a little icon in the top left that appears on hover.

HowToChart

(If you’re already using counters with Seq 1.3, you’ll need to recreate them before historical data will be indexed by the 1.4 preview.)

Quick(er) switching between views

A much-requested improvement: when no view is selected, the first 10 views will be shown in a list (saving a few clicks when switching between views).

ViewSwitching

Extended text operators

A bunch of work has gone into better string comparison functions in this version. Seq queries now support:

  • Contains(text, pattern)
  • StartsWith(text, pattern) and EndsWith(text, pattern)
  • IndexOf(text, pattern), and
  • Length(text)

In each of these, “pattern” can be case-insensitive, case-sensitive, or a regular expression. There’s some more information and examples in the documentation.

Date functions and @Timestamp

Events in Seq now carry a queryable @Timestamp property, and we’ve added a DateTime() function that can be used with it. Check out the documentation for some examples here.

Keep the feedback coming!

Download the preview, try it out, and let us know what you think! You know where to find me :) – and there’s also a Seq discussion group we’d love you to join, and a Seq Twitter account if you’d like to keep in the loop.

Serilog gets a mention at NDC Oslo 2014

It was really cool to see this session from NDC about Elasticsearch/Logstash/Kibana featuring Serilog from just after 16:00.

Monitoring your app with Logstash and Elasticsearch from NDC Conferences on Vimeo.

It’s fun watching Serilog presented by people who obviously “get it”. And, compared with the alternatives shown earlier in the session, it’s great to see just how easy Serilog is for generating quality structured logs.

(If you’re not using Serilog and interested in the demo code, it’s on GitHub, but please check out this tiny PR if it hasn’t made it through yet.)

One year of Serilog

I just pushed the first build of Serilog 1.3 to NuGet. This one includes a more flexible JsonFormatter and support for width specifiers in format strings. Not huge changes, but both called for obsoleting some existing methods, and with 1.2 at the venerable age of “.53″ it was time to rev and get back to the nice simple version “1.3.1”.

It occurred to me that we’ve now hit the one year mark in the Serilog project. Version 0.1 was announced on March 29th, 2013 actually!

If there was any doubt back then of the viability of “yet another logger” in the .NET ecosystem, it’s been well and truly dispelled in my mind. Sixteen of us have now contributed to the project, and what’s most exciting to me is that the developers extending, using and discussing Serilog are some of the best and brightest I know. It’s the kind of momentum that makes me confident we’ll see more use and growth in the next year.

For those who follow it, the mention of structured logging as a technology to “trial” in the January 2014 ThoughtWorks Technology Radar is also a good indicator that Serilog is aligned with the facilities .NET developers will come to expect and use widely.

Our 1.0 came only six months ago, so these are still early days, but there are now 38 packages tagged “serilog” on NuGet, and despite the more-than-occasional glitches in the counter ;) the core Serilog package has over 7,400 downloads.

Visits to http://serilog.net are also looking healthy:

Serilog-One-Year

April’s been a visibly good month, with a lot of interest stirred up by a discussion on .NET Rocks! where I did my best to “get the word out” about how Serilog has totally transformed my thinking about logging.

If you’re using Serilog it would be great to hear more about how it has worked for you, and where you think the project should be aiming next – get in touch here or on our discussion list!