To know an object is to lead to it through a context which the world provides. — William James (1842–1910) — a temporal trace of operations — is vital for any mission-critical system, no matter how big or small. Same was the case with our , which is why we wanted to get it right, right from the beginning. Logging maintaining Project-X framework — 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 . Contextual logging UltraESB We already knew , with almost everything that we need; but we needed more: log4j2 was offering contextual logging with its [CloseableThreadContext](https://logging.apache.org/log4j/2.x/manual/thread-context.html) implementation We needed a proper 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 through the whole codebase to find out where the bugger came from. log code grep 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 in case of our ). cluster ID 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 ) in case we need to. While we could have utilized a third-party wrapper such as we couldn’t find a wrapper that could readily fulfill all our demands. logback SLF4J Hence, as with the previous UltraESB, we wrapped log4j2 with , our own logging implementation. 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 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. x-logging x-logging ServiceLoader 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. ) or from a deployed , 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. Ruwan engine project If you are familiar with , this may all sound quite simple. For the rest of the crowd, it would be enough to mention that 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 ( ) of the calling thread; or, in English, every log line printed by that thread sees the parameter in its thread context (or in old-school jargon). [CloseableThreadContext](https://logging.apache.org/log4j/2.0/log4j-api/apidocs/org/apache/logging/log4j/CloseableThreadContext.html) CloseableThreadContext ThreadContext MDC 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 in the context try (CloseableThreadContext.Instance level1 = CloseableThreadContext.put("level", "1")) { // now the context has "1" as "level" // will see {level=1} as // the context logger.debug("Commencing operation"); // let's also put in a "clearance" value level1.put("clearance", "nypd"); // now, any log lines would see {level=1,clearance=nypd} logger.debug("Commencing operation"); // 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 context mutations */ // will see {level=2,clearance=fbi} logger.debug("Commencing investigation"); // putting in some more level2.put("access", "privileged"); // now context = {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 */ // {level=3,clearance=cia,access=privileged} logger.debug("Commencing consipracy"); } /* 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) */ // {level=2,clearance=fbi,access=privileged} logger.debug("Back to investigation"); } // same for exiting level 2 // {level=1,clearance=nypd}; access is gone! logger.debug("Back to operation"); } 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: In , the underlying engine of , a maintained at the base framework level is responsible for processing inbound messages on behalf of an belonging to a particular project. Project-X UltraESB-X worker threadpool integration flow We consider the thread to be in the project’s context only after the message has been injected to the 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 context. ingress connector system We generate logs throughout the whole process, so they should automatically get tagged with the appropriate context. 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 Internally, , and others will ultimately invoke a method: loggerA loggerM logImpl(code, message, params) // 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 interface: CloseableContext import java.io.Closeable; public interface CloseableContext extends Closeable { CloseableContext append(final String key, final String value); void close();} whose log4j2 variant ( , obviously) will manipulate instances in the same manner: Log4j2CloseableContext CloseableThreadContext 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 implementation together with the logger binding (via ), we know that will ultimately end up invoking the correct implementation. CloseableContext ServiceLoader LogContextProvider And that’s the story of contextual logging in our framework. x-logging Maybe we could also explain our log code governance approach in a future post; until then, happy logging!
