Logging in Style: log4j 2, Contextuality, Auto-cleanup... All with No Strings Attached!

Logging—maintaining a temporal trace of operations—is vital for any mission-critical system, no matter how big or small. Same was the case with our Project-X framework, which is why we wanted to get it right, right from the beginning.

Contextual logging—where each log line automatically records its originating logical context, such as whether it came from a specific unit or from the base framework—was something we have been looking forward to, based on our experience with logging on the legendary UltraESB.

We already knew log4j2 was offering contextual logging with its CloseableThreadContext implementation, with almost everything that we need; but we needed more:

1. We needed a proper log code governance mechanism where each log line contains a unique log code, indicating the subsystem, module (package) and even an exact "index" of the specific log statement, so that we would no longer need to grep through the whole codebase to find out where the bugger came from.
2. We needed to inject environmental variables and system properties, with a certain prefix, to be automatically injected to the logging context, so that specific applications could inject their runtime parameters to the logs (such as cluster ID in case of our Integration Platform).

We also needed to be API-independent of log4j2, as we should retain the freedom to detach from log4j2 and utilize a different logging framework (such as logback) in case we need to. While we could have utilized a third-party wrapper such as SLF4J we couldn't find a wrapper that could readily fulfill all our demands.

Hence, as with the previous UltraESB, we wrapped log4j2 with x-logging, our own logging implementation. x-logging consists of an API and a set of bindings to real logging frameworks (like log4j2 and logback), one of which can be plugged in dynamically at server startup time with Java's dear old ServiceLoader mechanism. This helped us to avoid leaking of log4j2-specific stuff into our implementations, as the log4j2-based implementation (and hence log4j2 itself) could be completely removed from the set of compile-time dependencies.

Ruwan from our team, who was also the originator of Project-X, hacked around with log4j2 for some time, and finally came up with a cool design to automatically propagate the current context of a log line, i.e. whether it originated from the platform (system, a.k.a. engine) or from a deployed project, and if it's the latter, other metadata of the project (such as the version). The coolest part was that this context automatically gets cleaned up once execution leaves that particular context.

If you are familiar with CloseableThreadContext, this may all sound quite simple. For the rest of the crowd, it would be enough to mention that CloseableThreadContext facilitates injecting key-value pairs to the logging context, such that when the context is closed, only the ones injected in the current context get cleaned up. The injected values are automatically made available to the logging context (ThreadContext) of the calling thread; or, in English, every log line printed by that thread sees the parameter in its thread context (or MDC in old-school jargon).

Okay, I admit the above might have been a bit hard to understand. Perhaps a sample snippet may do a better job:

// assume we are walking in, with nothing useful inside the context

try (CloseableThreadContext.Instance level1 = CloseableThreadContext.put("level", "1")) {

    // now the context has "1" as "level"
    logger.debug("Commencing operation"); // will see {level=1} as the context
    // let's also put in a "clearance" value
    level1.put("clearance", "nypd");
    // now, any log lines would see {level=1,clearance=nypd}

    // let's go deeper
    try (CloseableThreadContext.Instance level2 = CloseableThreadContext.put("level", "2").put("clearance", "fbi")) {

        // now both of the above "level" and "clearance" values are "masked" by the new ones
        // and yes, you can chain together the context mutations
        logger.debug("Commencing investigation"); // will see {level=2,clearance=fbi}

        // putting in some more
        level2.put("access", "privileged");
        // now context is {level=2,clearance=fbi,access=privileged}

        // still deeper...
        try (CloseableThreadContext.Instance level3 = CloseableThreadContext.put("level", "3").put("clearance", "cia")) {

            // "level" and "clearance" are overridden, but "access" remains unchanged
            logger.debug("Commencing consipracy"); // {level=3,clearance=cia,access=privileged}

        }

        // cool thing is, once you're out of the level3 block, the context will be restored to that of level2
        // (thanks to the AutoCloseable nature of CloseableThreadContext.Instance)

        logger.debug("Back to investigation"); // {level=2,clearance=fbi,access=privileged}
    }

    // same for exiting level 2
    logger.debug("Back to operation"); // {level=1,clearance=nypd}; access is gone!

}

logger.debug("Back to square one"); // {}; oh no, all gone!

This mechanism was ideal for our use, as we needed to include the current execution context of a thread along with every log line generated by that thread:

1. In Project-X, the underlying engine of UltraESB-X, a worker threadpool maintained at the base framework level is responsible for processing inbound messages on behalf of an integration flow belonging to a particular project.
2. We consider the thread to be in the project's context only after the message has been injected to the ingress connector of a particular integration flow. The worker thread is supposed to do quite a bit of work before that, all of which would be considered to belong to a system context.
3. We generate logs throughout the whole process, so they should automatically get tagged with the appropriate context.
4. Moreover, since we have specific error codes for each log line, we need to open up a new context each time we actually output a log line, which would contain the required log code in addition to the other context parameters.

So, the life of a thread in the pool would be an endless loop of something like:

// wake up from thread pool

// do system level stuff

loggerA.debug(143, "Now I'm doing this cool thing : {}", param);

try (CloseableThreadContext.Instance projectCtx = CloseableThreadContext.put("project", project.getName())
     .put("version", project.getVersion())) {

    // do project level stuff

    loggerM.debug(78, "About to get busy : {}", param);

    // more stuff, tra la la la
}

// back to system level, do still more stuff

// jump back to thread pool and have some sleep

Internally, loggerA, loggerM and others will ultimately invoke a logImpl(code, message, params) method:

// context already has system/project info,
// logger already has a pre-computed codePrefix

try (CloseableThreadContext.Instance logCtx = CloseableThreadContext.put("logcode", codePrefix + code)) {
    // publish the actual log line
}

// only "logcode" cleared from the context, others remain intact

We simulated this behaviour without binding to log4j2, by introducing a CloseableContext interface whose log4j2 variant (Log4j2CloseableContext, obviously) will manipulate CloseableThreadContext instances in the same manner:

import java.io.Closeable;

public interface CloseableContext extends Closeable {

    CloseableContext append(final String key, final String value);

    void close();
}

and:

import org.adroitlogic.x.logging.CloseableContext;
import org.apache.logging.log4j.CloseableThreadContext;

public class Log4j2CloseableContext implements CloseableContext {

    private final CloseableThreadContext.Instance ctx;

    /
     * Creates an instance wrapping a new default MDC instance
     */
    Log4j2CloseableContext() {
        this.ctx = CloseableThreadContext.put("impl", "project-x");
    }

    /
     * Adds the provided key-value pair to the currently active log4j logging (thread) context
     *
     * @param key   the key to be inserted into the context
     * @param value the value to be inserted, corresponding to {@code key}
     * @return the current instance, wrapping the same logging context
     */
    @Override
    public CloseableContext append(String key, String value) {
        ctx.put(key, value);
        return this;
    }

    /
     * Closes the log4j logging context wrapped by the current instance
     */
    @Override
    public void close() {
        ctx.close();
    }
}

Now, all we have to do is to open up an appropriate context via a nice management interface, LogContextProvider:

// system context is active by default

...

try (CloseableContext projectCtx = LogContextProvider.forProject(project.getName(), project.getVersion())) {

    // now in project context
}

// back to system context

And in logImpl:

try (CloseableContext logCtx = LogContextProvider.overlayContext("logcode", codePrefix + code)) {
    // call the underlying logging framework
}

Since we load the CloseableContext implementation together with the logger binding (via ServiceLoader), we know that LogContextProvider will ultimately end up invoking the correct implementation.

And that's the story of contextual logging in our x-logging framework.

Maybe we could also explain our log code governance approach in a future post; until then, happy logging!