Distributed Logging With NServiceBus
I recently had an interaction with an NServiceBus customer and noticed that they are pushing the log of their import process all the way to the UI. While this may be normal in some cases, but why do you put all the technical details, including exceptions, stack trace, in case of errors in that customer facing log window? The answer was: it is hard for us to gather all the relevant information from a distributed process that’s running in a handful of microservices. When something goes wrong, it is hard for us to gather all the relevant information.
It all boiled down to this: while each individual service capture all the detail of a successfull and failed job, the logs go into individual log files on those services. It is hard to connect these logs across different services. In a nutshell, distributed logging is hard. But does it have to be?
Let’s see how you can get a view of a distributed process by using a structured logging framework. In this example I’m using NServiceBus, Serilog and Seq.
To understand the ‘context’ (pun intended) of a production error, you’re going to need a lot more information that just the exception and the stack trace. Imagine the error being thrown in a multi-tenant web application. Which customer request is causing this error? What are the request/header information for that header?
Typically the code that logs the message, would look something like this:
static ILog log = LogManager.GetLogger<SubmitOrderHandler>();
And the output would look something like this:
Even if you use a logging server like Seq, it is still hard to understand which logs are related to the same workflow.
But surely, we can do better.
To connect your workflow, you need to choose an identifier that would connect all messages in your workflow. With the identifier flowing through your services you can later connect your log entries using a LogContext. Usually things like an Order ID, JobID and identifiers like that can be picked but it depends on your code.
With Serilog, the code that’d use the
OrderNumber as the added context would look like this:
using (LogContext.PushProperty(nameof(message.OrderNumber), message.OrderNumber))
We can immediately see the benefit. In Seq, now you can filter for a specific
OrderNumber and see all the logs across the services related to that order number.
Serilog supports ‘Enrichers’ which are independent modules of code adding context to the logs, similar to LogContexts.
Instead of the previous code-snipper, you can encapsulate that in an Enricher. With a bit of an extension method, you can tie that in to your NServiceBus message handler:
public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
and the your message handler can now do this:
var logger = context.GetOrderWorkflowLogger(message);
Did you notice anything extra on the last screenshot?
If you don’t know, NServiceBus supports the concept of ‘ConversationID’ which has a similar purposes: connecting all messages in the same workflow. The way it works is that the first message being sent gets a new ConversationID and the subsequent messages sent in the (handler) context of that message automatically will get the same ID. This way you can identify a group of messages belong to the workflow.
When using Serilog in your NServiceBus endpoints, you should get a reference to the logger via the
IMessageHandlerContext object. That way, all that information will also get logged which would be very useful for production use.
In fact, the conversation information is used in ServiceInsight to visualize the messages. If you are a NServiceBus platform, ServiceInsight can be used to visualize messages in a conversation.
I have used the NServiceBus showcase codebase for this post but I have somewhat modified it to use Serilog. You can find the modified code on this repository.