Structured Logging in Sitecore

In Sitecore Symposium 2019, Sitecore announced company’s plan to move Sitecore Platform to SaaS based model. If you want to know more about it, you can read this FAQ. As Sitecore is moving to SaaS, which will require completely revamping the architecture, they will be building on ASP.NET Core. With many things that will change in this transition, Sitecore will definitely going to look at the logging strategy in the platform. With all certainty they will move to Structured Logging because ASP.NET Core itself adopted Structured Logging as the logging strategy. In fact, Sitecore introduced Structured Logging using Serilog in their newest modules like xConnect and Sitecore Host.

In this article, we will discuss about Structured Logging to understand what is expected in future version of Sitecore SaaS. We will look into Sitecore’s current text based logging strategy based on Log4net and discuss about approach to convert logging of existing Sitecore applications to Structured Logging.

What is Structured Logging

The idea of logging information in computer program existed from the very beginning. Every computer language has some form of printf statement. In the very beginning printing statement in the console was the way of debugging applications. Later on debugging issues in complex applications became difficult. Specially, illusive issues that happen in the production environment required us to persist the logging statement in some place, in files, database etc. This required industry to come up with some logging frameworks that will enable us to use logging as an Aspect Oriented Programming (AOP) and enable us to capture information in different storage of our choice. Log4j/Log4net is a good example of this and has a wide acceptance in the industry. Log4net is an interface based framework for implementing AOP based logging in applications. Although it comes with several implementation of Appenders (Log4net terms for different way to persist information), it doesn’t restrict anyone to implement new Appenders or change existing one. Sitecore went one step ahead. They took Log4net source code and implemented entire logging in Sitecore.Logging module. This gives them better control over Log4net versioning and implementation. Also, it helps us to separate implementation specific logging from Sitecore internal logging. If you look at Sitecore implementation bin folder, you will not find any log4net.dll, because everything related to logging is in Sitecore.Logging.dll.

Is Log4net good enough for what we need? Let’s look at how log4net is described in Apache log4net About page.
The Apache log4net library is a tool to help the programmer output log statements to a variety of output targets. log4net is a port of the excellent Apache log4j™ framework to the Microsoft® .NET runtime.
We can see log4net doesn’t say what to send in output log statement and that creates a huge problem in consuming logs. In other words, there is no structure in what we can send to output log, there is no rule. Log4net doesn’t stop us creating structure in the log statement, it’s just that, the framework was built based on Text Logging. In Text Logging, there is no separation between variables and values. Everything is included in the message. A Text Logging looks like below (taken from real sitecore log). When we log this way, we lose information because we cannot for example find all values of ‘interval’ easily.

35364 12:21:02 INFO  Starting periodic task "ExpiredMessagesCleanup" with interval 00:01:00
35364 12:21:02 INFO  Starting periodic task "CleanupTrackedErrors" with interval 00:01:00

The same logging in Structured Logging looks like below.

thread=35364, time=12:21:02, level=INFO, task="ExpiredMessagesCleanup", interval=00:01:00
thread=35364, time=12:21:02, level=INFO, task="CleanupTrackedErrors", interval=00:01:00

What Structured Logging provides is key/value pair, and that makes parsing logs much easier. But, what matters most is programming mind set, because, if we add the logging output to a message variable, it will become nothing but Text Logging. When we are adopting Structured Logging, we need to think what we need to capture to render logging that is easily navigable to troubleshoot difficult application issues. To help with this, Structured Logging standardized the process that we will discuss next. Logging framework such as Serilog is based on this Structured Logging concept and provides great tooling and programming extensions for implementing Structured Logging in applications.

Message Template

One thing should be mentioned that, Structured Logging is much harder for human to read than Text Logging because habitually, it is easier for us to read sentences than key/value pair. It is a problem that needed to be addressed because most of the time when we are troubleshooting issues, after querying or navigating through logs, we will read the log entries. This is something that has been addressed using Message Template. For example, if we want to capture above mentioned log entries using Message Template, we will log like below.

log.Information("Starting periodic task {taskname} with interval {interval}", taskname, interval);

The above will produce structured log entries like below.

{
    "thread":"35364",
    "time":"12:21:02",
    "level":"INFO",
    "template":"Starting periodic task {taskname} with interval {interval}",
    "properties":{
        "taskname":"ExpiredMessagesCleanup",
        "interval":"00:01:00"
    }
}
{
    "thread":"35364",
    "time":"12:21:02",
    "level":"INFO",
    "template":"Starting periodic task {taskname} with interval {interval}",
    "properties":{
        "taskname":"CleanupTrackedErrors",
        "interval":"00:01:00"
    }
}

Since the log entries are captured in Message Template format it is possible to render the entries in human readable format by replacing the properties in the template. At the same time since the properties are captured separately, it is also machine readable. One other benefit of using template is that, we can generate unique hash from the Message Template and use that to group the messages. To learn more about Message Templates visit https://messagetemplates.org/

Events and Event Types

Every entry captured in the log is due to an event that occurred. There is no different meaning of event in Structured Logging. Similar to Text Logging Structured Logging has event level like debug, information, warning etc.
In logging, level is used to reduce the number of logging events captured in the application to minimize the impact on performance as well as less number of event to parse in case of troubleshooting. Despite of this ability, our experience of troubleshooting issues by looking at log entries most of the time is overwhelming. Even if we set minimum level for logging to info, there are so many unrelated log entries, finding the entries that are related to issue becomes very difficult. If the issues could be categorized into different event types, we could exclude the events that we are not interested in and narrow our search. Something like facet filtering in search. In Text Logging this is done using Event Type, but it requires significant effort because we need to plan ahead to create the Event Types and then follow through that plan in application building. In Structured Logging we can use Message Template itself as the Event Type. If we are not interested in certain type of message, we can exclude those messages based on the Message Template. It is even easier if Message Template can be converted into hashes because each type of Message Template hash will be unique. For example, if we want to exclude all message of the below kind, we can exclude all messages created from the Message Template included in the message.

{
    "thread":"35364",
    "time":"12:21:02",
    "level":"INFO",
    "template":"Starting periodic task {taskname} with interval {interval}",
    "properties":{
        "taskname":"ExpiredMessagesCleanup",
        "interval":"00:01:00"
    }
}

Enrichment

Enrichment in Structured Logging is decorating logs with information to build a context so that we can correlate log entries. For example, in Sitecore application if someone says, a component in a page is showing error sometime for some users connected to a specific CD server. Diagnosing this kind of problem requires to build context in the log to narrow down the search. If we can add information like, Sitecore ItemId, UserId, Rendering ItemId, Data SourceId, Machine Name (which CD) etc., we may find that personalization rule for a group of users is failing because certain items were not published properly in problematic CD server. In Structured logging, Enrichment allows us to add information like Machine Name, ThreadId, even custom properties in the log to build context. Correlating log entries is specially difficult in asynchronous programming where you cannot really use Time or ThreadId easily to correlate log messages. In that case events can be wrapped using a MessageId to identify them belongs to one group. We will discuss more about Enrichment with examples in the second part of this blog about Serilog.

Log Parsing Tools

Tools do not have really anything to do with Structured Logging concepts, but Structured Logging makes it easier to build tools for slicing and dicing logs. In text logging, since there is lack of structure, after capturing logs, we use generic tools like LogParser, grep to parse logs. With logs captured using Structured Logging concept, it is easier to build tool to parse log, create reports & charts and send alerts. Seq is one such tool to parse logs captured using Serilog. We will look into Seq in the second part of this blog series.

Final Words

In this blog article I discussed the concepts of Structured Logging and tried to associate the concepts with Sitecore logging. Understanding these concepts will help us to understand logging in Sitecore in future SaaS version. Also, my goal is to see if I can convert the logging in the current versions of Sitecore to Structured Logging to some extent so that I can take advantage of fantastic tooling and extensions available in Serilog. That’s coming in future blog posts. Stay tuned.

References

About Himadri Chakrabarti

I am a solutions architect and a Sitecore MVP. I am focused on Sitecore and Ecommerce development. Opinions expressed in my blogs are my own.
This entry was posted in Debugging, Logging, Sitecore and tagged , , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.