Description

While some time ago it was quite common to output log statements to standard out, people usually use logging frameworks nowadays that give more control about what should be logged and where the log entries should go.

However, it turns out that such logging frameworks have some feature gems that are not widely known or used. To name a few:

  • Diagnostics Contexts (also known as Mapped Diagnostics Context (MDC) or Nested Diagnostics Context (NDC)) help to store additional context information for all succeeding log statements. Usage examples for such contexts are the login name of the current user, correlation IDs in order to enable cross-application log tracing or transaction IDs to have the possibility to filter all log entries that belong together.
  • Additional log levels or markers help to make it easier to filter the log stream. It is a good advice to think about the marker and log design at the beginning of the project and try to agree on a common way to phrase log statements.
  • Asynchronous appenders (i.e. log emitter) allow high-throughput logging, which lower impact on the application’s performance.
  • Structured log formats produce a machine-readable output. Usually, log files are written using a more or less standardized text output. Log files in XML or JSON can be parsed and digested easily and allow for better filtering since more information, like diagnostics contexts, is always available in these formats.
  • Filters enable context-based logging and can dispatch log entries to different log appenders. For instance it is possible to log warnings only but switch to debug logging for a specific user.

In some environments it turns out to be problematic to rely on a single logging API. This could be the case if the application runs within a container or container-like framework that already employs a configured logging framework. In order to be independent of concrete logging frameworks, logging facades like SLF4J should be preferred over using the framework’s API directly.

Despite the focus on the software development, logging is also an operations topic. Often it turns out to be difficult to get recent log files from the operations team. Another pain point is that useful log information is scattered across multiple log files, stored at different locations on different systems. Log aggregation tools such as Splunk, Logstash, Apache Flume or fluentd can consume and unify log data from different sources (e.g. files, syslog, network), can trigger alerts or index the log stream in order to make them searchable. Now, with tools like Kibana, log data of a system of systems can be easily analyzed and visualized. Correlation IDs contained in the logs can be used to trace certain business-related requests across multiple distributed systems easily.

Using such features makes the problem analysis easier and more data is available in a standardized fashion.

Experiences

Most projects write log files in a more or less sophisticated fashion, in many cases log messages are phrased in a rather unstructured way. It turns out that a well-designed logging concept helps to make the log stream easier to understand. This concept should provide some guidelines regarding which log level should be used in which situation, how the wording of log messages could be unified and which additional log levels or markers shall be used for what purpose.

Tip: In a customer project we used an object-relational-mapping (ORM) tool for a database independent access layer. The data access was inherently transactional and created a lot of database traffic so that deadlock situations on the database were expected and properly handled with a delayed retry mechanism.

While this approach worked quite well, we got frequently complaints from the operations team, which reported a number of ERROR log messages along with longish stacktraces that set their alarm bells off. These log messages were written by the ORM tool whenever a DB deadlock was experienced. Since the application could perfectly deal with this situation this was not an error anymore and should have been logged as WARN or INFO at best. The problem was that a third-party framework used the wrong log level and was thus causing a lot of confusion. Bear this in mind when working on a framework-like codebase and thinking about log levels.

Risks

  • An excessive amount of log statements is likely to have negative impact on the application’s performance. The impact is however manageable by using
    • guarded log statements that will only be constructed if a certain log level is enabled,
    • asynchronous appenders (like the disruptor-based approach used by Log4J 2),
    • context-sensitive logging (e.g. to enable debug logs only for a certain scenario or user).
  • Collecting and indexing a huge amount of log data requires additional storage, approx. by factor 10. Think of retention policies in order to make the data stream manageable.

Applicability

This pattern should always be considered.

Consequences

  • Improved understanding of the runtime behavior of an application or a system of systems.
  • Log messages are well-structured and more meaningful as they carry more context information (in case MDCs are used).
  • This pattern is an important enabler for a successful Runtime Artifact Analysis.
  • Instrument System is very similar to this pattern, however it is limited to a temporary instrumentation that is needed during the Analysis phase to identify or scope a certain problem that cannot be isolated without modifying the code.