Logging Tips for Power Users: Contextual Logging

Logs are often treated as independent items. Events are generated independently of each other, and while they may share some information, their main purpose is to provide information specific to a given situation. This makes it difficult to explore more details about the event such as the cause of the event, the actions leading up to the event, or even additional details surrounding the event itself.

Contextual logging is an approach that encourages not just adding additional useful data to log events, but also sharing that data across related events. With contextual logging, data tokens are added to and removed from log events over the course of the application’s runtime. Depending on your application’s workflow, some of these tokens can be shared across multiple log events, or even across the entire application. In the meantime, your log events still retain core logging information such as method names and stack traces.

In this post, we’ll explain how to use contextual logging in your applications. This post uses Java as an example, but the same principles apply to any logging framework that can support a logging context.

Log4j 2 and Thread Context

Log4j 2 is a popular logging framework for Java applications. One of the features introduced in Log4j 2 is the Thread Context, which lets you store data that can be accessed by various logging methods. Logging calls access the Thread Context with little to no additional configuration. Data stored in the Thread Context is unique to each thread and persists for the lifetime of the thread, making this a popular option for multi-user applications and web services.

How Is Contextual Logging Useful?

Contextual logging lets you tag log events with additional data without having to modify your logging calls. In addition to making your logs more detailed, this also lets you relate log events based on a common data point, such as a unique identifier. You can add to and remove from the context over the course of the application without necessarily having to keep track of what’s being stored in the context and where it appears in your logs.

Imagine an e-commerce application that lets users select multiple items from a database, add them to an online shopping cart, and complete a transaction. We want our logs to give us insight into user behaviors, load times, and errors encountered. There are dozens of unique data points available for tracking, including:

• Requests from the users’ browsers to the web server
• User session identifiers
• Usernames and user IDs
• Pages that users navigate to
• Identifiers for new and completed transactions

When a log event is triggered, these data points can pinpoint the exact condition of the application during the event, allowing you to analyze and debug more effectively.

Monitor, Map, and Trace Actions

Using the same e-commerce application from above, we can track the user’s flow through the checkout process. When the user first accesses the application, we generate a unique session identifier and associate it with the user. If the user registers or logs into his or her account, we can then add a user ID to the context. If the user initiates a purchase, we generate a transaction ID and add that as well. As this data is added to the context, newly generated log events will automatically append the data to their output. Over time, this creates a history of actions where we can watch the user progress through the application. Additionally, if an error did occur, we could use all of these data points to better determine the root cause of the error.

Identify Parameters Leading to Failures

Storing contextual data does more than just help create a history of events: it provides detailed information about the environment leading up to and during errors. Imagine that the application throws an exception during the checkout process. A typical log will display an error message and a stack trace showing where the problem occurred. With contextual logging, we’re given additional information that identifies the conditions surrounding the log, such as:

• The ID of the session that generated the error
• The user who experienced the error
• The user’s location in the application
• The ID of the transaction or product that caused the error

By combining these data points with our log history, we can determine the exact conditions that led up to the exception and better understand how to prevent similar errors from occurring in the future.

Summarizing Events

In addition to displaying trends and user behavior, contextual logs also make it possible to create summaries of your application’s performance. For example, if you want to determine where your application is experiencing frequent errors, you can use tools such as Loggly to search, extract, and group error-level logs by exception, by class, or even by user. The Troubleshooting with Java Logs section of the Loggly Ultimate Guide to Logging provides detailed information on summarizing Java log events, particularly when using Thread Context.

Generating Alerts

Alerts are a crucial component of any log management system. Contextual logs provide a trove of additional data that can help identify performance issues, errors, and outliers. In addition to detecting application-wide scenarios such as frequent errors and low response times, we can detect more specific scenarios.

For instance, by logging usernames provided during the login process, we can detect an excessive number of failed logins for the administrator account. By logging user IDs and transactions, we can detect a large number of purchases during a short amount of time, indicating potential fraud or abuse. By detecting a large number of errors on a particular page, we can quickly discover and fix bad code. Adding useful data to logs gives you more opportunities to monitor for specific types of events.

How Do I Implement Contextual Logging?

This section demonstrates contextual logging using the Thread Context in Log4j 2, although you can use a similar pattern with other languages like C#, Javascript, and more. With Log4j’s Thread Context, there are two ways to manage content: using the Thread Context Stack and the Thread Context Map.

The Thread Context Stack acts like a traditional software stack. You can add or remove items from the top of the stack and reference them by their order in the stack or by the data stored in the item itself. Meanwhile, the Thread Context Map stores elements as key-value pairs. While both methods are valid, the Thread Context Map can provide more flexibility.

Thread Context Stack

Using the Thread Context Stack, you can place (push) and remove (pull) values to and from the top of the stack. The Thread Context is managed by the static ThreadContext class, meaning we can modify the Thread Context without having to initialize a ThreadContext object.

In this example, we have an application that stores information about the user as he or she logs in and out. We’ll use ThreadContext.push() and ThreadContext.pop() to record and remove the username as he or she logs in and out respectively.

 

This adds the following output to JSON-formatted logs generated while the user is logged in:

Thread Context Map

Like the Thread Context Stack, the Thread Context Map is managed through the static ThreadContext class. Instead of pushing and popping, use the put() and remove() methods to modify values in the Thread Context:

 

This results in the following lines added to log events:  

You can clear the Thread Context before the thread is terminated by using ThreadContext.clearStack(), ThreadContext.clearMap(), or ThreadContext.clearAll() for the stack, the map, or the entire thread respectively.

Reviewing Logs

Using a logging service such as Loggly lets you easily aggregate, search, and correlate log events. Because of this, we recommend storing your logs in JSON format for easier parsing.

With Loggly, events are automatically parsed and added to the Field Explorer as they arrive from your application. The following image uses JSON logs with data stored in the Thread Context Map to trace an admin user as he or she logs in, encounters a broken page, then logs out.

You can fine-tune your search results by adding more terms to the search box. For instance, if you want to find all events that were logged by the admin user from the settings page, you can add a condition to the search box that filters on another context map key:

Adding more context lets you create more granular searches, but it comes at the cost of larger log files. If you want to learn more about Java’s Thread Context, take a look at the Java Logging Basics section of the Ultimate Guide to Logging. If you’re ready to take advantage of contextual logging in your applications, sign up for a free Loggly trial.

The Loggly and SolarWinds trademarks, service marks, and logos are the exclusive property of SolarWinds Worldwide, LLC or its affiliates. All other trademarks are the property of their respective owners.