Last updated at Thu, 08 Aug 2019 17:22:44 GMT
In a previous article, The Benefit of Having an Enterprise Logging Policy, I presented the case for always using self-describing data formats when logging information. Using self-describing formats, such as key-value pairs and JSON, saves time and effort in terms of indexing and subsequently querying your logs on the backend. Also, logs that use a self-describing data format are easier to understand by anyone, at any time.
In this article I am going to present concrete ways to implement such a practice when using Log4Net. However, the concepts I am going to share with you can be applied to many other logging tools, Log4J for example.
First I am going to show you how to create self describing log entries in key-value and JSON format using the <conversionPattern> in the <Layout /><Log4Net /> section of a .Net configuration file. Then, I’ll should you how to use NewtonSoft’s JsonConvert utility class to ensure proper JSON formatting when logging from within a .NET application.
I am going to assume that you have a basic operational knowledge of configuring and using Log4Net in a .NET application.
The Code for this Article
You can find the code that I created to demonstrate the key points discussed in this article on GitHub, here.
Enforcing Log Entry Consistency
Probably the easiest way to ensure that you are logging information using a self-describing data format is to get up as close as possible to the point of log entry. The typical pattern in the Software Development Lifecycle is that a developer makes log entries from within the application code. Then, when the application is deployed, a Systems Engineer or somebody in a similar role will decide how log data will be formatted for presentation and storage. (Please see Figure 1, below.)
Thus, the point that is “closest to the metal” in terms controlling log output is within the application’s configuration file, specifically within the definition of a given Log4Net Appender. Appender configuration allows a System Admin to format log output and the destination for that output independent of the application code. However, for as much power and flexibility as adjusting the configuration file provides to the System Admin, a poorly structured log entry can have an impact on the validity of the data format being supported. So, we need to be careful. We’ll cover the ensuring format validity later in this article when I discuss formatting data entries as JSON.
An Appender is the code within the Log4Net plumbing that processes a LoggingEvent. Every time a log entry is made within an application, a LoggingEvent is raised and that LoggingEvent information is passed as an object to one or many Appenders that are defined in the <Log4Net /> section of a .NET app.config or web.config. (Please see Figure 2, below.)
Log4Net ships with a number of Appenders. There is an Appender that will send LoggingEvent information to a file. This is the FileAppender. There is an Appender that will send LoggingEvent information to the console terminal window. This is the Console Appender. Logentries publishes an Appender that sends LoggingEvent data directly to LogEntries for storage and subsequent analysis. Also, should you need very particular behavior in a Log4Net appender, you can write your own.
You tell Log4Net which Appenders to use and how to use each via your application’s app.config, or web.config, if you are writing a ASP.NET application. As mentioned above, each Appender that is defined within the <Log4Net /> section of the configuration file will process a LoggingEvent according to the Appender’s definition. You configure the <layout><conversionPattern… /></layout> section of a given Appender to define how the Appender will render LoggingEvent information to a log. There is a lot of power and flexibility when it comes to defining a <conversionPattern />. You declare the LoggingEvent fields you want to include in your log entry by using a percent sign (%) before the field name. For example, you can just send the LoggingEvent’s message to the log using %message. Or you can send LoggingEvent %message, the assembly sending the log data (a.k.a, the %logger), the current %date formatted to your need, and the Level (%level) of the loggingevent, INFO for example. Also, You can add custom embellishments to the conversionPattern. For example, Listing 1 below…
Listing 1: A conversion with some embellishment formatting
<conversionPattern value=" Log Date is %date{ddd MMM dd yyyy}, Level is %level, Sent from %logger, with the message - %message %newline" />
… can output Listing 2 to the console:
Listing 2: Log data output according to conversion pattern
Log Date is Sat Apr 16 2016, Level is INFO, Sent from MyLogger.Program, with the message - Just starting up, all is well
As mentioned before, the Log4Net <conversionPattern /> offers customization abilities that are very powerful and flexible. We can take advantage of the Log4Net conversion pattern to ensure that the data that being logged is always self-describing, regardless of the log data that is being emitted by the application.
The LoggingEvent object has many properties, any or all that can be displayed in a given conversion pattern. Also, Log4Net provides the ability for the programmer to add custom properties to suit a given need. The way you declare the format and information to display in a given log entry is by working with the properties of the PatternLayout class. You can read the details of the PatternLayout class here.
Defining a Self-Describing Conversion Pattern
Let’s take another look at the log entry sent as output to the console, as defined in Listing 1 above,
Log Date is Sat Apr 16 2016, Level is INFO, Sent from MyLogger.P
rogram, with the message - Just starting up, all is well
While the output is self-describing in terms of human interpretation, it is less than optimal for indexed storage. The fields, Date, Level, Logger and Message are hard described inconsistently. Over the long term, anybody who wants to gather information from such entries is going to have to do a lot of search and retrieval using regular expressions. However, consider the following conversion pattern, shown below in Listing 3:
Listing 3: A Conversion Pattern for logging data in key-value pairs
<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender">
<layout type="log4net.Layout.PatternLayout">
<conversionPattern value=""date":"%date{ddd MMM dd HH:mm:ss zzz yyyy}", "level":"%level", "logger":"%logger", "message":"%message" %newline" />
</layout>
</appender>
The conversion pattern shown above in Listing 3, will output the following in Listing 4:
Listing 4: The result of a conversion pattern that produces information in key-value pairs
"date":"Sat Apr 16 2016","level":"INFO","logger":"KeyValueLogger.Program","message":"Just starting up, all is well"
Listing 4, above is an example of key-value pair formatting. Key-value formatting is self-describing to both human and machine intelligence. The pattern lends itself to easy indexing, and subsequently easy search and retrieval. In fact, some tools such as Logentries have built in intelligence that recognizes log data being entered in key value format. The tool will parse the entry and index it automatically, as shown below in Figure 3.
By using our understanding of using Log4Net conversion patterns to create key-value output of log data, we’ve increased the usability of our log data. And, we did this without having to twiddle with any log emission code within an application.
Working with JSON
Log4Net allows us to apply custom conversion patterns to produce JSON. The conversion pattern shown in Listing 5 below is a JSON representation of the information we expressed as key-value pairs above.
Listing 5: A Conversion Pattern for logging data in JSON
<conversionPattern
value="{"EntryDate":"%date{ddd MMM dd HH:mm:ss zzz yyyy}",
"Level":"%level",
"Logger":"%logger",
"Message":"%message"}
%newline"
Notice please that in Listing 5, above, the expression, "e, is used to declare a quotation mark. Listing 5 will produce the JSON output shown below in Listing 6.
Listing 6: We can use a conversion pattern for format a log entry in JSON.
{"EntryDate":"Sat Apr 16 14:04:24 -07:00 2016","Level":"INFO","Logger":"JsonLogger.Program","Message":"Just starting up, all is well"}
The benefit of using JSON as a log format is that it’s an easy format to parse and index later on. In fact, when we submit the JSON to Logentries, the platform not only accepts the entry as shown below in Figure 4, but will also segment and index the JSON for easier querying later on. (Please see Figure 5.)
A Gotcha
Beware! Formatting a LoggingEvent to JSON can be very tricky. Remember please, essentially JSON is a string that is structured to conform to a special formatting convention. I’ve gotten in trouble more than once creating invalid JSON just because one quotation mark is in the wrong place. For example, please consider the following:
The string of JSON above looks good, right. But, when the string is processed by the following conversion pattern, things go awry.
When we impose quotation characters (") that surround the property declaration, %message, on the string, {“startup”:”All is well”}, which is essentially a JSON object, we make the JSON invalid, as shown below. (The corrupting quotation marks are shown in red.)
And when we run the string of JSON we’ve created through a JSON validator, such as JSONLint, we get the following, as shown below in Figure 6.:
It turns out that the application was emitting a handmade string of JSON and the conversion pattern was imposing its own JSON formatting logic on that string. Thus, when the string was rendered by the conversion pattern, invalid JSON was created.
In order to fully enjoy the benefit of the self-describing nature of JSON, it’s best to come up with a way to make sure that the message data being logged to Log4Net is valid JSON from the gitgo, not some string data that we have shoehorned into a JSON format.
The good news is that there is a way to ensure JSON that is safe to format later on in a configuration file. The trick is to use the Newtonsoft’sJsonConvert utility class to create JSON when logging from within a .NET application.
Ensuring Consistent JSON in Application Logging
As I demonstrated above, shoehorning data from a LoggingEvent.Message into JSON at the <conversionPattern /> level of an application’s configuration file can be an accident waiting to happen. One unexpected quotation mark or comma within the message can make the entire JSON invalid. Thus, if we decide to submit log data to our log collectors in JSON format, user defined data such as LogEvent.Message must be converted to JSON in a consistent and safe manner. The technique I like to use is to use James Newton-King’s JsonConvert utility class to convert POCOs (Plain Old CSharp Object) that describe a message I want to log as JSON, which I then pass as a log message.
Consider the code below in Listing 7.
Listing 7: Emitting a log message as an object converted to JSON ensures safe conversion patterns when formatting to JSON downstream
using log4net;
using Newtonsoft.Json;
using System;
namespace JsonAutoLogger
{
class Program
{
private static readonly ILog log = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);
static void Main(string[] args)
{
log4net.Config.XmlConfigurator.Configure();
while (true)
{
var msg = new
{
Phase = "Application Startup",
Entered = DateTime.UtcNow,
Comment = "All is well"
};
log.Info(JsonConvert.SerializeObject(msg));
Console.WriteLine("");
Console.WriteLine("Strike the Enter key to Log again. Type 'q' to exit");
String x = System.Console.ReadLine();
if (x.ToLower().Equals("q")) Environment.Exit(0);
}
}
}
}
Notice please the code in Listing 7 above creates an object, msg, that contains the information we want to log. The object is then converted to JSON using JsonConvert.SerializeObject() and that JSON is logged using log.Info(). (The logging code is shown in bold, blue font above.)
Listing 8 below shows the conversion pattern that is used to format the log data that gets sent on for logging. Notice please in Listing 8, that %message is NOT surrounded by quotation marks. There is no need to. Remember, the message that the developer logged is a JSON object. JSON defines an object using open and closed parentheses, ({}). In the conversion pattern below, the property, Message, does NOT describe a string. Message describes a JSON object. Thus. the parentheses cannot be surrounded by quotes. It’s the way JSON works.
Listing 8: %message is not surrounded by quotation marks because is already passed to the conversion pattern as a string
<conversionPattern value="{"EntryDate":"%date{ddd MMM dd HH:mm:ss zzz yyyy}","Level":"%level","Message":%message} %newline" />
Listing 9 below shows the JSON that appears in the log file. Again, notice that Message is defined as a JSON object, { …. } and is NOT surrounded by quotation markss.
Listing 9: Emitting a log message from an application by converting a POCO produces valid JSON.
{"EntryDate":"Sat Apr 16 19:50:38 -07:00 2016","Level":"INFO","Message":{"Phase":"Application Startup","Entered":"2016-04-17T02:50:37.8183393Z","Comment":"All is well"}}
And, were we to beautify the JSON, it will look like the code shown below in Listing 10.
Listing 10: Beautified JSON with a message created within the application using JsonConvert
{
"EntryDate": "Sat Apr 16 19:50:38 -07:00 2016",
"Level": "INFO",
"Message": {
"Phase": "Application Startup",
"Entered": "2016-04-17T02:50:37.8183393Z",
"Comment": "All is well"
}
}
Now, should we be using Logentries to collect our log data, the JSON we submitted in Listing 10 above will be parsed and indexed according to the JSON structure submitted. Notice please in Figure 7 below, that the JSON object is segmented according to the JSON structure submitted, with the properties of the object associated with the JSON’s Message property listed as distinct fields.
Key Benefits of Using JsonConvert
There are two benefits of using JsonConvert. The first is that at the enterprise level, JsonConvert provides an easy way for ensuring that developers are creating self-describing log information in JSON format. Remember, implementing simple procedures to support a policy is the easiest way for the enterprise to adopt a policy. The procedure description is simple:
Use NewtonSoft’s JsonConvert in your .NET code to facilitate logging message information in JSON format.
The second benefit is that JsonConvert reduces the risk of a developer creating log message information that will cause corruption later on.
Putting It All Together
The world is full of log data that is hard to understand and harder to analyze. Formatting log data so that it is self-describing is easier both in terms of human readability and machine analysis. The more popular self-describing data formats are key-value pairs and JSON. A logging platform such as Logentries can consume log data formatted in key-value pair or JSON easily. In addition, Logentries will parse, segment and index such formats automatically for fast, easy querying.
Popular logging technologies such as Log4Net allow you to structure log data into a self-describing format within the application’s configuration file. Formatting log entries at the configuration file level is useful for System Admins that are far away from the day to day coding process. However, sometimes defining the structure of a log entry at the level of the configuration file can create entries that are invalid to the given format, particularly when it comes to JSON. In such a case, a policy and procedures for creating self-describing log entries in JSON need to be implemented at the developer level. Developers can use a technology such as NewtonSoft’s JsonConvert to create log messages in JSON that will be safe to use in a conversion pattern that is defined in the application’s configuration file.
Implementing a policy for using self-describing logging formats at the enterprise level will go a long way toward ensuring that log data is consistent and easy to analyze. Supporting such a policy with easy to follow procedures that provide immediate benefit will increase the likelihood of enthusiastic adoption by all who create log data and those who care about working efficiently and effectively with log data.
Learning More
- Log4Net conversion Pattern formatting
- Key-Value Pairs and JSON Parsing in LogEntries
- Querying JSON in Logentries
Ready to get started? Sign up for a free Logentries account today.
