Flow Tracing

Log4j API provides convenience logging methods to aid the tracking of the data flow through an application, which is referred to as flow tracing. Logging implementations can choose to generate specialized log events allowing users to handle these messages different from the rest – see Example configuration.

Flow tracing is known to help with the following use cases:

  • Troubleshooting without requiring a debugging session

  • Helping educate new developers in learning the application

Usage

Logger provides following methods for flow tracing purposes:

traceEntry()

Marks the entry to a block

traceExit()

Marks the exit from a block

catching()

Reports caught exceptions

throwing()

Reports exceptions that are either discarded or unlikely to be handled

The most used traceEntry() and traceExit() methods are intended to mark the entry and exit points of a particular block of code:

Example traceEntry() and traceExit() usage
public void someMethod() {
    LOGGER.traceEntry(); (1)
    // method body
    LOGGER.traceExit(); (2)
}
1 traceEntry() marks the entry to the block
2 traceExit() marks the exit from the block

Both traceEntry() and traceExit() also accept parameters. You can use them to track the input and output of the associated block:

Example traceEntry() and traceExit() usage with arguments
public String someMethod(String input) {
    logger.traceEntry(null, input); (1)
    // method body
    String output = ...;
    return logger.traceExit(output); (2)
}
1 traceEntry() marks the entry to the block along with the input
2 traceExit() marks the exit from the block along with the output

The catching() method can be used by an application when it catches an exception that it will not rethrow, either explicitly or attached to another exception:

Example catching() usage
public void someMethod() {
    try {
        // Business logic
    } catch (Exception error) {
        logger.catching(error); (1)
    }
}
1 catching() reports the caught exception

The throwing() method can be used by an application when it is throwing an exception that is unlikely to be handled, such as a RuntimeException. This will ensure that proper diagnostics are available if needed.

Example throwing() usage
public void someMethod() {
    try {
        // Business logic
    } catch (RuntimeException error) {
        throw logger.throwing(error); (1)
    }
}
1 thrown() reports the caught exception that is about to be rethrown. Plus, rethrowing the exception, contrary to the catching() example suppressing the exception. 
public void someMethod() {
    try {
        // Let's assume an exception is thrown here
        String msg = messages[messages.length];
    } catch (Exception ex) {
        logger.throwing(ex); (1)
    }
}
1 The throwing() method logs exceptions that are thrown and not caught.

Aspect-oriented programming

Logging has been a notorious example for demonstrating aspect-oriented programming (AOP). For instance, using AOP, you can inject logging statements to methods that match a particular footprint, e.g., all public methods in com.mycompany package. With a couple of lines of AOP instructions, you can log input and output of all matching functions. Flow tracing methods fits like a glove to this AOP use case. You can see a demonstration of this in the log4j-samples-aspectj project demonstrating how you can implement this use case using Log4j API flow methods and Spring Boot AspectJ support.

Implementation

This section explains how flow tracing is implemented by different logging implementations.

Log4j Core

Log4j Core, the reference implementation of Log4j API, implements the flow tracing methods such that

Log events

Log4j Core implements the flow tracing methods such that the generated log events are decorated to accommodate any need to selectively handle them:

Method Level Markers Message

traceEntry()

TRACE

ENTER, FLOW

EntryMessage extending from FlowMessage

traceExit()

TRACE

EXIT, FLOW

ExitMessage extending from FlowMessage

throwing()

ERROR

THROWING, EXCEPTION

Plain message

catching()

ERROR

CATCHING, EXCEPTION

Plain message

Configuration

Flow tracing implementation of Log4j Core can be configured using the following system properties:

log4j2.flowMessageFactory

Env. variable

LOG4J_FLOW_MESSAGE_FACTORY

Type

Class<? extends FlowMessageFactory>

Default value

DefaultFlowMessageFactory

Fully qualified class name of a FlowMessageFactory implementation to be used by all loggers.

Logback

Logback is another logging implementation for the SLF4J logging API, just like Log4j Core is a logging implementation for the Log4j API. Using Log4j-to-SLF4J bridge, Logback can be configured to consume Log4j API.

Log4j-to-SLF4J bridge implements flow tracing methods such that log events are generated with same marker and level changes of Log4j Core. They only differ in generated message types, since SLF4J has no extensible message contract like Log4j, but plain String-based messages. This effectively means Logback also has access to the stated marker and level changes while using Log4j API flow tracing methods.

Example configuration

In this section, we will share logging implementation configuration examples to filter on flow tracing log events.

Log4j Core

Log4j Core is the reference implementation of Log4j API. In the example configurations below, we will employ a Pattern Layout depending on the associated markers of the log event:

  • XML

  • JSON

  • YAML

  • Properties

log4j2.xml snippet
<MarkerFilter marker="FLOW" onMatch="ACCEPT" onMismatch="NEUTRAL"/>(1)

<Appenders>
  <Console name="CONSOLE">
    <PatternLayout>
      <MarkerPatternSelector defaultPattern="%d %5p [%t] %c{1} -- %m%n">(2)
        <PatternMatch key="ENTER" pattern="%d %5p [%t] %c{1} => %m%n"/>(3)
        <PatternMatch key="EXIT" pattern="%d %5p [%t] %c{1} <= %m%n"/>(4)
      </MarkerPatternSelector>
    </PatternLayout>
  </Console>
</Appenders>
log4j2.json snippet
"MarkerFilter": { (1)
  "marker": "FLOW",
  "onMatch": "ACCEPT",
  "onMismatch": "NEUTRAL"
},

"Appenders": {
  "Console": {
    "name": "CONSOLE",
    "PatternLayout": {
      "MarkerPatternSelector": {
        "defaultPattern": "%d %5p [%t] %c{1} -- %m%n",(2)
        "PatternMatch": [
          {(3)
            "key": "ENTER",
            "pattern": "%d %5p [%t] %c{1} => %m%n"
          },
          {(4)
            "key": "EXIT",
            "pattern": "%d %5p [%t] %c{1} <= %m%n"
          }
        ]
      }
    }
  }
},
log4j2.yaml snippet
MarkerFilter: (1)
  marker: "FLOW"
  onMatch: "ACCEPT"
  onMismatch: "NEUTRAL"

Appenders:
  Console:
    name: "CONSOLE"
    PatternLayout:
      MarkerPatternSelector:
      defaultPattern: "%d %5p [%t] %c{1} -- %m%n" (2)
      PatternMatch:
        - key: "ENTER" (3)
          pattern: "%d %5p [%t] %c{1} => %m%n"
        - key: "EXIT" (4)
          pattern: "%d %5p [%t] %c{1} <= %m%n"
log4j2.properties snippet
filter.0.type = MarkerFilter (1)
filter.0.marker = FLOW
filter.0.onMatch = ACCEPT
filter.0.onMismatch = NEUTRAL

appender.0.type = Console
appender.0.name = CONSOLE
appender.0.layout.type = PatternLayout
appender.0.layout.patternSelector.type = MarkerPatternSelector
appender.0.layout.patternSelector.defaultPattern = "%d %5p [%t] %c{1} -- %m%n (2)
appender.0.layout.patternSelector.properties.0.type = PatternMatch
appender.0.layout.patternSelector.properties.0.key = ENTER
appender.0.layout.patternSelector.properties.0.pattern = %d %5p [%t] %c{1} => %m%n (3)
appender.0.layout.patternSelector.properties.1.type = PatternMatch
appender.0.layout.patternSelector.properties.1.key = EXIT
appender.0.layout.patternSelector.properties.1.pattern = %d %5p [%t] %c{1} <= %m%n (4)
1 Accepting log events marked with FLOW regardless of their level
2 By default, log event messages will be formatted with a -- prefix
3 Log events marked with ENTER (that is, generated by traceEntry()) will have their message formatted with a ⇒ prefix
4 Log events marked with EXIT (that is, generated by traceExit()) will have their message formatted with a ⇐ prefix

Logback

Logback is another logging implementation for the SLF4J logging API, just like Log4j Core is a logging implementation for the Log4j API. Using Log4j-to-SLF4J bridge, Logback can be configured to consume Log4j API.

Below we will use a combination of EvaluatorFilter, MarkerFilter, and OnMarkerEvaluator in Logback to adapt the formatting pattern of messages written to console based on flow tracing specific markers:

logback.xml snippet
<turboFilter class="MarkerFilter">(1)
  <Marker>FLOW</Marker>
  <OnMatch>ACCEPT</OnMatch>
</turboFilter>

<appender name="CONSOLE_DEFAULT" class="ConsoleAppender">
  <filter class="EvaluatorFilter">(2)
    <evaluator class="OnMarkerEvaluator">
      <marker>ENTER</marker>
      <marker>EXIT</marker>
    </evaluator>
    <onMismatch>ACCEPT</onMismatch>
    <onMatch>DENY</onMatch>
  </filter>
  <encoder class="PatternLayoutEncoder">(3)
    <pattern><![CDATA[%d %5p [%t] %c{1} -- %m%n]]></pattern>
  </encoder>
</appender>

<appender name="CONSOLE_FLOW_ENTER" class="ConsoleAppender">
  <filter class="EvaluatorFilter">(4)
    <evaluator class="OnMarkerEvaluator">
      <marker>ENTER</marker>
    </evaluator>
    <onMismatch>DENY</onMismatch>
    <onMatch>ACCEPT</onMatch>
  </filter>
  <encoder class="PatternLayoutEncoder">(5)
    <pattern><![CDATA[%d %5p [%t] %c{1} => %m%n]]></pattern>
  </encoder>
</appender>

<appender name="CONSOLE_FLOW_EXIT" class="ConsoleAppender">
  <filter class="EvaluatorFilter">(6)
    <evaluator class="OnMarkerEvaluator">
      <marker>EXIT</marker>
    </evaluator>
    <onMismatch>DENY</onMismatch>
    <onMatch>ACCEPT</onMatch>
  </filter>
  <encoder class="PatternLayoutEncoder">(7)
    <pattern><![CDATA[%d %5p [%t] %c{1} <= %m%n]]></pattern>
  </encoder>
</appender>

<root level="WARN">
  <appender-ref ref="CONSOLE_DEFAULT"/>
  <appender-ref ref="CONSOLE_FLOW_ENTER"/>
  <appender-ref ref="CONSOLE_FLOW_EXIT"/>
</root>
1 Accepting log events marked with FLOW regardless of their level
2 In CONSOLE_DEFAULT appender, excluding all log events marked with ENTER and EXIT
3 In CONSOLE_DEFAULT appender, log event messages will be formatted with a - prefix
4 In CONSOLE_FLOW_ENTER appender, accepting only log events marked with ENTER
5 In CONSOLE_FLOW_ENTER appender, log event messages will be formatted with a → prefix
6 In CONSOLE_FLOW_EXIT appender, accepting only log events marked with EXIT
7 In CONSOLE_FLOW_EXIT appender, log event messages will be formatted with a ← prefix