Tag Archives: Logging

Loading a Log4j Configuration for a specific EJB

You can load and unload a specific Log4j 2 configuration file for a given EJB. How? Use @PreDestroy and @PostConstruct. This gives you separately deployable EJBs with separate Log4j configurations. Ka-Pow!

For example:

public class MySessionEJB implements SessionBean {

    private static final String LOGGER_CONFIG = "/path/to/log4j2.xml";
    private static final String LOGGER_CONTEXT_NAME = "MySessionEJB";
    private static LoggerContext logctx;
    private static Logger logger;

    private void postConstruct() {
        logctx = Configurator.initialize(LOGGER_CONTEXT_NAME, LOGGER_CONFIG);
        logger = logctx.getLogger("com.whatever.myejb");

    private void preDestroy() {

Happy Coding,
Gary Gregory

Apache Log4j 2.7 is out!

log4j-logo-2-7Apache Log4j 2.7 is heading out to Maven Central. Here’s are the highlights of what’s new since 2.6.2.


  • The RoutingAppender can be configured with scripts.
  • A new Appender, the ScriptAppenderSelector can create another Appender as specified by a Script.
  • Users can now inject context data from other sources than ThreadContext. Values can be any Object, not just Strings.
  • The SocketAppender now supports IO buffering.
  • Added the ability to generate Log4j 2 XML configuration file from a ConfigurationBuilder.
  • Hello Scala! We’ve added Logging APIs for Scala 2.10 and 2.11.
  • Added options to exclude stack trace from JSON, XML and YAML layouts.
  • Added Core API Configurator.shutdown(LoggerContext, long, TimeUnit).
  • FileAppender and RollingFileAppender can create files on-demand.
  • PatternLayout added a color ANSI option to %message and %xThrowable.
  • org.apache.logging.log4j.core.LoggerContext now implements Closeable.
  • Add ThreadContextMap2 interface supporting method putAll(Map<String, String>).
  • Add JUnit Rule implementations to manage the thread context.
  • The Core AbstractConfiguration and AbstractManager now track its LoggerContext; add Configuration.getLoggerContext().

Continuing the Asynchronous Epic

  • We’ve added support for java.util.concurrent.LinkedTransferQueue to the AsyncAppender.
  • Added optional support for the Conversant DisruptorBlockingQueue in AsyncAppender.
  • Added optional support for JCTools MPSC bounded lock-free queue in AsyncAppender.

Continuing the GC-free Epic

  • Continuing the GC-free epic, we’ve added support for garbage-free ThreadContext map. This is disabled by default, and users need to enable this explicitly.
  • Also in GC-free-land, we changed LogEvent‘s internal data structure for context data to be garbage-free. We added the method LogEvent#getContextData() and deprecated getContextMap().

Continuing the Builder Epic

  • Added Builders for the ConsoleAppender, FileAppenderRoutingAppenderSocketAppender, and ServletAppender (and deprecated factory methods).
  • Builders can be generic.
  • Builder can subclass another Builder.

And bug fixes as well, for which you can just see the Log4j site.

Happy Log4j Logging!


Changing log levels in Log4j2

How do you change log levels in Log4j 2 when the Logger API does not have a setLevel() method?

The Configurator class provides several methods to change levels in Log4j. An important feature to understand before using these APIs is that logger names are hierarchical, see Refining Logging with Hierarchical Loggers.

Configurator.setAllLevels(String, Level)

The Configurator.setAllLevels(String, Level) method sets the level of the given named logger and all child loggers. Recall that in Log4j, loggers are hierachical. If you have the loggers com.foo.acom.foo.b, and com.foo.c, and you call setAllLevels("com.foo", Level.DEBUG) then all the loggers I listed will be set to DEBUG as will "com.foo". A logger "com.bar" will remain as is.

Configurator.setLevel(Map<String, Level>)

The method Configurator.setLevel(Map<String, Level>) will set each named logger to its Level from the map. No child loggers will be affected unlike setAllLevels(String, Level).

For example:

Map&amp;lt;String, Level&amp;gt; map = new HashMap&amp;lt;&amp;gt;();
map.put(&quot;com.foo&quot;, Level.DEBUG);
map.put(&quot;com.bar&quot;, Level.DEBUG);

This will set the loggers "com.foo" and "com.bar" to DEBUG but no existing child loggers of either will be affected. If you create a new child logger though, that child logger will inherit its level from its parent.

Configurator.setLevel(String, Level)

The method Configurator.setLevel(String, Level) sets the named logger to the given level without affecting child loggers (unlike setAllLevels(String, Level)).


Finally, Configurator.setRootLevel(Level) sets the level of the root logger to the given level without affecting child loggers. The root logger is the topmost logger with a name of "" (the empty string).

Happy Coding,
Gary Gregory

The Art of Logging: Advanced message formatting

In this post, I’ll show you how to format your Log4j logging message like a pro.

Let’s start with a bland and inefficient logging statement:

logger.debug("There are " + getUserCount() + " users logged in now.");

This is lame for three reasons:

  1. You are always building the full string before calling debug()
  2. You are always calling getUserCount()
  3. Both of the above happens even if debug logging is disabled!

In the old days of logging, you avoided these problems with more code like this:

if (logger.isDebugEnabled()) {
  logger.debug("There are " + getUserCount() + " users logged in now.");

This is quite verbose and unnecessary if you are using Log4j 2. Instead, use this:

logger.debug("There are {} users logged in now.", getUserCount());

We’ve removed one level of lameness: the final string is only built when debug logging is enabled. The complete message only gets built when debug logging is enabled: the “{}” parameter marker is replaced by the value returned by getUserCount(). The getUserCount() method is still called whenever the debug() method is called. That part is still Lame.

As I point out in this post, Log4j 2.4 and Java 8 come to the rescue with lambdas to clean this up as follows:

logger.debug("There are {} users logged in now.", () ->; getUserCount());

All lameness is now removed:

  • The getUserCount() function is only called when debug logging is enabled. This happens because the expression “() -> getUserCount()” does not call the getUserCount() method before debug() is called. Instead, Java creates a block of code that Log4j executes later, if it needs the result.
  • The complete message is only built with the result of getUserCount() when debug logging is enabled.

The only possible drawback is that the getUserCount() function is called a little later in the code path which could be an issue if the method relies on precise and exact timing or position on the stack, that would be unusual but possible.

Next up is the actual format of the message.

Using “{}” parameter markers causes Log4j to call toString() on each argument you pass to logger methods like debug().

This is ugly when it comes to printing large numbers for example:

There are 2147483647 users logged in now.

Instead, I want something that looks civilized like this:

There are 2,147,483,647 users logged in now.

You can do this using a different kind of logger and a format string:

Logger logger = LogManager.getFormatterLogger();
logger.debug("There are %,d users logged in now.", () -> getUserCount());

A formatter logger let’s you use patterns like “%,d” and all the power of the stock Java java.util.Formatter class.

You can format numbers like this as well:

logger.debug("Gain or loss: $ %(,.2f", delta);

Gives you:

Gain or loss: $ (12,582.19)

You can get extra fancy with dates:

Calendar c = new GregorianCalendar(1918, MAY, 11);
logger.info("Richard Feynman's Birthday: %1$tb %1$te, %1$tY", c);

Gives you:

Richard Feynman's: May 11, 1918

Super powerful, super nice.

The only caveat is that you will not get the same performance out of a formatter logger as you would out of the default logger. Still, pretty neat.

Happy Coding,
Gary Gregory

Writing clean logging code using Java 8 lambdas

In this article, I will show you how to clean up your logging code using Apache Log4j 2.4 and Java 8 lambdas.

Log4j is a great logging framework, and the upcoming version — 2.4 — includes support for Java 8 lambdas. Lambda expressions are new to Java 8 and provide a simple and compact way to represent a method interface using an expression.

Let’s get started; I’ve seen a lot of logging code that looks like this:

final String that = "that";

// Creates logger
final Logger logger = LogManager.getLogger();

// Builds a String
logger.debug("This " + this + " and " + that + "with " + compute());
Why do I use the final keyword? See my previous post The final KISS in Java.

The string building is pretty nasty, so for the first clean, we’ll irefactor the log message construction into something more palatable using Log4j parameter markers:

logger.debug("This {} and {} with {} ", this, that, compute());

The "{}" is called a parameter marker and defines the spot where an argument will replace these characters. In this example, we have three "{}" parameter markers and three parameters (this, that, and compute()) in addition to the message template.

This is all neat and prettier than the previous incarnation but there is still a problem. The call to compute() may be expensive. Ideally, we want logging calls to be as inexpensive as possible when logging at that call site’s level is disable.

In plain logging, you must guard the logging call like this:

// Guards against calling compute
if (logger.isDebugEnabled()) {
  logger.debug("This {} and {} with {} ", this, that, compute());

So that more code (three lines vs. one) and one golden opportunity to shoot yourself in the foot? Can you see how? Yes, by mismatching the “is” method to the log method, in this case isDebugEnabled() must match debug() to get the desired behavior.

This is the kind of implosion I’ve seen:

// No logging takes place here!
if (logger.isDebugEnabled()) {
  logger.trace("This {} and {} with {} ", this, that, compute());

Mission invisible: You have debug logging enabled for your logger but you get no logging output because the logging call is at the TRACE level.

With Java 8 and Log4j 2.4, we can go back to writing a one-liner:

// Uses Java 8 lambdas to build arguments on demand
logger.debug("I am logging that {} happened.", () -> compute());

The key expression is worth repeating:

() -> compute()

In simple terms, this tells Java: “Build me an object that refers to the compute() method and pass that as a method argument.” Log4j will ask this magic object to call the compute() method only when it decides that the log level is enabled for the logger and it is time to build the full log message from the message template.

This is so powerful! You can now express in one line a potentially expensive logging call and keep it succinct.

The only ugly part here is that when you use this technique, you must specific all arguments with lambdas:

logger.debug("This {} and {} with {} ", 
  () -> this, () -> that, () -> compute());

Not great, granted, but hopefully better than before.

Under the hood

A lambda expression is a method that does not have a name. This is not like any other kind of method and it’s new to Java 8. You use this to pass behavior around your system, as if it were a piece of data. The idea of behavior as data is the take away here. Very powerful concept folks!

As you saw above, a lambda expression (with 0 arguments) looks like this:

() -> compute()

More generally, the pattern is:

(x, y) -> x + y

A lambda expression can take more than one argument, in this case two. This example creates a function that adds two numbers together.

If we wanted to assign this function, we would use a BinaryOperator:

BinaryOperator<Integer> adder = (x, y) -> x + y;

The compiler infers types for us in this example, which we could also write to explicitely declare its types:

BinaryOperator<Integer> adder = (Integer x, Integer y) -> x + y;

The last item in this brief walkthrough of note is the functional interface, which is an interface with a single method used as the type of a lambda expression. In the case of Log4j, this interface is:

package org.apache.logging.log4j.util;

public interface Supplier<T> {

     * Gets a value.
     * @return a value
    T get();

The only reason this class exists in Log4j 2.4 is to still be able to run with Java 7 as a requirement instead of Java 8. If you are using Java 8, you can use Java 8’s stock java.util.function.Supplier interface.

Log4j defines some methods with Supplier arguments instead of used Object or a generic type. For example, here is a fragment from the org.apache.logging.log4j.Logger interface:

  * Logs a message with parameters which are only to be constructed if the logging level is the {@link Level#DEBUG
  * DEBUG} level.
  * @param message the message to log; the format depends on the message factory.
  * @param paramSuppliers An array of functions, which when called, produce the desired log message parameters.
  * @since 2.4
void debug(String message, Supplier<?>... paramSuppliers);

This article showed you how to combine Log4j with Java 8 lambdas and also serves a gentle introduction to the Log4j API and lambda basics.

Happy Coding,
Gary Gregory

The Art of Test Driven Development: Logging JUnit Test Results

JUnit saves your test results to a file (using XML, plain, brief or failure formatters). If you use Maven, you can convert these files into an HTML report easily. However, that means waiting for a build to complete. If you want to see your test results while a Maven or Ant build is running, you must watch the command line.

In an IDE like Eclipse, you can watch the JUnit view to see tests progress. Wouldn’t it be nice to be able to do whatever you want with tests results on the fly?

What we’ll show you here as an alternative is logging your test results while JUnit runs your tests. This gives you all the power of Log4j to direct test results all over the place, from a simple console, to a database, a JMS queue, or any of the long list of appenders Log4j provides. You can provide your own Log4j appender as well for custom processing.

The basic mechanism that lets us do this is JUnit’s TestWatcher rule. Let’s introduce the TestWatcher with a simple example that logs test results to a StringBuilder. The example dumps the builder’s contents on the console when the test finishes.

package com.garygregory.log4j;

import org.junit.AfterClass;
import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class StringBuilderTestWatcherTest {
    private static final String EOL = 

    private static StringBuilder builder = new StringBuilder();

    public static void afterClass() {

    public TestWatcher watchman = new TestWatcher() {

        protected void failed(Throwable e, Description description) {
            if (description != null) {
            if (e != null) {
                builder.append(' ');
            builder.append(" FAIL");

        protected void succeeded(Description description) {
            if (description != null) {
            builder.append(" OK");

    public void testFails() {
        // test

    public void testSucceeds() {
        // test

In this example, the test class implements the TestWatcher rule directly. JUnit calls each method you annotate with @Test one after the next. JUnit calls the failed() method when a @Test method fails and gives it a description and an exception. JUnit calls the succeeded() method when a @Test method completes normally, no JUnit Assert calls failed, no unexpected exceptions.

The method afterClass() (annotated with JUnit’s @AfterClass) runs after all test methods have run and outputs the contents of the StringBuilder.

The console output is for the StringBuilder example is:

testSucceeds(com.garygregory.log4j.StringBuilderTestWatcherTest) OK
testFails(com.garygregory.log4j.StringBuilderTestWatcherTest) java.lang.AssertionError FAIL

It’s easy to imagine growing and morphing this StringBuilder implementation into all sorts of things: to write the results to a file, with your own format, or send results to a database, and so on.

Instead of going that way though, you should bridge to Log4j and reuse its powerful and rich feature set, which let’s you do all that and much more. The power of Log4j comes from the simplicity of its API combined with rich configurations you create in XML, JSON, or YAML. Log4j 2.4 also provides a programmatic configuration API, but that’s a separate topic.

To log our results to Log4j, we replace the StringBuilder with a Logger:

package com.garygregory.log4j;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class Log4jTestWatcherTest {

    private static Logger logger = LogManager.getLogger();

    public TestWatcher watchman = new TestWatcher() {

        protected void failed(Throwable e, Description description) {
            logger.error(description, e);

        protected void succeeded(Description description) {

    public void testFails() {
        // test

    public void testSucceeds() {
        // test

In this example, we still embed an implementation of TestWatcher in the test itself, but this time the methods call on its Logger. When a test fails, we log at the ERROR level, and when a test succeeds, we log at the INFO level.

The console output is for the Log4j example is:

2015-09-14 20:25:57,173 INFO [main][com.garygregory.log4j.Log4jTestWatcherTest] testSucceeds(com.garygregory.log4j.Log4jTestWatcherTest)
2015-09-14 20:25:57,175 ERROR [main][com.garygregory.log4j.Log4jTestWatcherTest] testFails(com.garygregory.log4j.Log4jTestWatcherTest)
  at org.junit.Assert.fail(Assert.java:86)
  at org.junit.Assert.fail(Assert.java:95)
  at com.garygregory.log4j.Log4jTestWatcherTest.testFails(Log4jTestWatcherTest.java:32)

The next obvious step is to abstract this TestWatcher in a class:

package com.garygregory.log4j;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.rules.TestWatcher;
import org.junit.runner.Description;

public class Log4jTestWatcher extends TestWatcher {

    private final Logger logger;

    public Log4jTestWatcher() {
        logger = LogManager.getLogger();

    public Log4jTestWatcher(String loggerName) {
        logger = LogManager.getLogger(loggerName);

    protected void failed(Throwable e, Description description) {
        logger.error(description, e);

    protected void succeeded(Description description) {

And reuse it in the test:

package com.garygregory.log4j;

import org.junit.Assert;
import org.junit.Rule;
import org.junit.Test;
import org.junit.rules.TestWatcher;

public class Log4jTestWatcherTest2 {

    public TestWatcher watchman = new Log4jTestWatcher();

    public void testFails() {
        // test

    public void testSucceeds() {
        // test

This is short and sweet, compare it to our first listing!

Boom! All the power of Log4j and JUnit combined.

Happy Coding,
Gary Gregory

The Art of Test Driven Development: Understanding Logging

Modern logging framework include the concepts of levelsloggers, markers, and filters. How and when should you use each? This is what I want to clarify based on discussions recently taking place on the Log4j user mailing list.

While logging is obviously a Martha Stewart-like “good thing”, what, when, and how to log might not be obvious to some. The how can be quite tricky, or not even possible with older frameworks. This article will clarify basic and advanced logging concepts using Java and Apache Log4j 2 as our reference platform.

Log4j 2 is the best Java logging library out there, I claim. Yes, better than Slf4j, Logback, and without a doubt, JUL. Granted, I am partial, as one of its contributors.

Central to any logging system is the log event, this is the piece of information you are sending to the log system, like “hello, I just started running.” Let’s start with the simplest concept: the log event’s level.

Understanding Log Levels

Log4jLevelsI think of levels as “how important is this event” and “who needs to know this”. Some of the art of logging is deciding who your audience is. To help your development team chase down a bug, you want to make sure that your app logs interesting events at the DEBUG and TRACE level. This is different than “what it is I am telling my audience”, which is where loggers come in.

To help you rate the importance of log events, Log4J provides the following levels: FATAL, ERROR, WARN, INFO, DEBUG, and TRACE. When I enable a level, Log4j logs these events at that level and all levels above it. For example, enabling WARN events will show me WARN through FATAL events, but not DEBUG through TRACE. In addition, Log4j bookends these levels with two special levels: OFF and ALL.

Let’s look at logging events in an authentication module. A user successfully logging in is normal and logs an INFO event. The module rejects a user after he enters the wrong password and logs a WARN event. After three unsuccessful attempts, the module locks out this user, and logs an ERROR event:

INFO : User alice logged in.
WARN : User bob entered an invalid password.
ERROR: User bob entered an invalid password three times, user locked out.

Then from a different part of the app, the email agent, for example:

DEBUG: Loading user bob from database jdbc:...
INFO : Emailed user bob: three login attempts rejected, user locked out.
ERROR: Email to alice bounced back; subject: Your weekly summary.

Depending on who does the logging, the meaning of what is normal vs. an error can be very different.

To wrap up this section, I usually configure logging when I start the application, through a configuration file. For example, telling Log4j to log all events at the WARN level and above. This lets me see only non-mundane events, stuff I should probably pay attention to. It is also possible to reconfigure Log4j while an application is up and running, a topic I’ll leave outside the scope of this article; it’s worth noting that the Log4j can watch its configuration file for changes.

Using Custom Log Levels

Advanced logging frameworks like Log4j allow you to define custom levels. Custom levels can help you understand levels better by applying the level concept to your application domain. Let’s take a little detour and look at some interesting level nomenclatures.
DEFCON levels
My favorite example is a War Games module that implements the five defense readiness conditions (DEFCONs); the alert states used by the United States Armed Forces:

“It prescribes five graduated levels of readiness (or states of alert) for the U.S. military, and increase in severity from DEFCON 5 (least severe) to DEFCON 1 (most severe) to match varying military situations.”[1]

The U.S. Department of Defense uses exercise terms when referring to DEFCON levels. The intent being to preclude confusing exercise commands with actual operational commands. The exercise term are: COCKED PISTOL (DEFCON 1), FAST PACE, ROUND HOUSE, DOUBLE TAKE, and FADE OUT (DEFCON 5).

DEFCON levels
Name Description Color
DEFCON 1 Maximum force readiness. White
DEFCON 2 Armed Forces ready to deploy and engage in less than 6 hours. Red
DEFCON 3 Air Force ready to mobilize in 15 minutes. Yellow
DEFCON 4 Above normal readiness. Green
DEFCON 5 Normal peacetime readiness. Blue

The DEFCONs are perfect candidates for custom log levels, as are their exercise terms.

You can also imagine a set of custom levels based on the Saffir-Simpson hurricane wind scale.

All North Atlantic and Eastern North Pacific major hurricanes (at least Category 3 on the Saffir-Simpson Hurricane Scale)

This graphic shows all North Atlantic and Eastern North Pacific major hurricanes (at least Category 3 on the Saffir-Simpson Hurricane Scale)

The National Hurricane Center defines the the Saffir-Simpson Hurricane Wind Scale as “a 1 to 5 rating based on a hurricane’s sustained wind speed. This scale estimates potential property damage. Hurricanes reaching Category 3 and higher are considered major hurricanes because of their potential for significant loss of life and damage. Category 1 and 2 storms are still dangerous, however, and require preventative measures. In the western North Pacific, the term “super typhoon” is used for tropical cyclones with sustained winds exceeding 150 mph.”

Saffir-Simpson Hurricane Wind Scale (more)
Category Sustained Winds Damage
5 (major) 157 mph or higher
137 kt or higher
252 km/h or higher
Catastrophic damage will occur.
4 (major) 130-156 mph
113-136 kt
209-251 km/h
Catastrophic damage will occur.
3 (major) 111-129 mph
96-112 kt
178-208 km/h
Devastating damage will occur.
2 96-110 mph
83-95 kt
154-177 km/h
Extremely dangerous winds will cause extensive damage.
1 74-95 mph
64-82 kt
119-153 km/h
Very dangerous winds will produce some damage.

This is another great example where domain levels would make a great example for custom log levels.

I hope these examples make it clear, if not already, that the level is about the relative importance of log events, regardless of who sends events.

To recap: A log level describes how important an event is: Is this a low-level step, or a rare and dangerous once-in-a-100-year event?

Next up are loggers, the kind of logging object an application interfaces with the most often.

Understanding Loggers

An application send log events like “I woke up” to the logging system through a logger.

The log event includes a level so what the application is really saying is, “Here is an interesting bit of information (nothing alarming); I just work up.”

A car could log a warning event saying, “Hey, driver, I’m running low on gas!” In code, this usually looks something like this:

logger.warn(“I’m low on gas.”);

A better message would include how much gas remains:

logger.warn(“I’m low on gas; {} gallons remaining.”, gallonsRemaining);

In this example, the {} is a parameter marker.

A logger has a name, in this case, we could call ours “car”.

If you imagine a large enough system, using the same logger to log all events will make it harder to find any single event or an interesting subset out of the whole event set. Let’s say my system includes my house, office, home office, kitchen, each room in the house, people, cars, toys, appliances, and so on. You can see that we will end up with a lot of logging events, from all over the place. To remedy this issue, you use a distinct logger for each kind of object and give each one a unique name.

If I want to analyze my driving and still be alerted of all other important events, I can now configure Log4j to log all car events at the DEBUG level and all other loggers at the WARN level.

Refining Logging with Hierarchical Loggers

Let’s take this a step further, looking at logging for our kitchen subsystem, and imagine that we look at all events for one day, regardless of the levels involved.

Every time the refrigerator door opens, I get an event, when it closes, another event. Same for the kitchen door, the oven door, the dishwasher door; you get the idea. The refrigerator can also warn me when its water filter needs replacing. The oven can tell me when preheating to a preset temperature is done, when the timer goes off and my cake is done.

What I then get is a flood of events from the kitchen logger, even if I can throttle the importance of events through levels, I still get to hear from all my appliances. What if I am only interested in the oven? Now, I know what you’re thinking: “Gary, just create one logger for each appliance”. “Well, yes you’re right” I’d say, but what would you call each logger? “I’d call them refrigerator, dishwasher, oven door, oven timer and so on”.

OK, but what if want to listen to all kitchen events again? Not just the one appliance? I’d have to set the level on each appliance logger, if I have dozens (imagine hundreds) of loggers, that’s quite a pain. There should be a way I can set the level for the whole kitchen, including everything in it.

And there is: By using hierarchical loggers.

To create a logger hierarchy, all you have to do is use periods in the name of your loggers, kind of like with internet domains. For example:

  • Kitchen
  • Kitchen.Oven
  • Kitchen.Oven.BottomOven
  • Kitchen.Oven.BottomOven.Door
  • Kitchen.Oven.BottomOven.Timer
  • Kitchen.Oven.BottomOven.Light
  • Kitchen.Oven.TopOven.Door
  • Kitchen.Oven.TopOven.Timer
  • Kitchen.Oven.TopOven.Light
  • Kitchen.Dishwasher
  • Kitchen.Refrigerator
  • Kitchen.Refrigerator.Door
  • Kitchen.Refrigerator.Filter
  • Kitchen.Refrigerator.Light
  • Kitchen.Refrigerator.Freezer.Door
  • Kitchen.Refrigerator.Freezer.Light
  • And so on

If my configuration only sets the Kitchen level to INFO, then all loggers that start with the string Kitchen inherit its level, INFO. In addition, if I configure the Kitchen.Oven logger to DEBUG, then all loggers that start with the string Kitchen.Oven will log at the DEBUG level. That’s how level inheritance works. Pretty cool and very powerful.

On the coding side, a common and pragmatic practice is to use one static logger for each class, named with the fully qualified name of the class (meaning the package name is included, like com.example.appliance.oven).

By carefully naming your loggers, you can get precisely defined log events, suitable for all manners of clever filtering, searching, and analysis.

You can already see that with just two concepts, levels and hierarchical loggers, you can get a world of well-defined log events at your fingertips, allowing you to analyze and debug your system to your hearts content, in live applications or post-mortem.

Top Gun Logging with Markers

The next ingredient in our logging soup is the event marker, which adds another level (pardon the pun) of information (again, sorry) to a log event. A Log4j marker has a name, and yes, it too can be hierarchical, but let’s leave that bit for another article. So, what is a marker? The way I like to look at it, is that a marker qualifies the kind of event I am signaling, like a tag on a blog post. This is very handy when many parts of the system, using different loggers, log the same kind of event. For example, every time a user opens and closes a door, whether that be an appliance door, a garage door, a doggy door or a POD (a Plain Old Door). This would sure be handy for security monitoring.

How would you only log open and close door events using loggers and levels. You can assume that door events are logged at… what? Maybe some appliances log door events at the INFO level and others at the DEBUG level. What if doors from a third party library log this kind of event at TRACE, another twist!

Noodle on that one for a minute…

Well, tricky, isn’t it? If I have loggers like Kitchen.Refrigerator.Door and Kitchen.Refrigerator.Door, the common root is Kitchen, not Door, so setting Kitchen to INFO is not what I want because I will get INFO events from all kitchen loggers! And what about the appliance that logs door events at the DEBUG level? That approach is dead on arrival.

Well, what about the reverse domain name trick? For each logger I could create another logger with the name in reverse, one word at time, where Kitchen.Refrigerator.Door becomes Door.Refrigerator.Kitchen. Then I can say set the Door logger to INFO and get all Door events! That would work for a given level but it sure is nasty! Two loggers for each appliance? But it’s worse, I’d need more reversed names for my Filters, Lights, and so on. Worse of all, this does not account for appliances that logs door events at the DEBUG and TRACE level! Nope, can’t be done with this reverse hack.

That’s when Markers come to the rescue. The code in all your classes that contains a door changes from:

logger.info(&quot;Door opened&quot;);
logger.info(&quot;Door closed&quot;);


logger.info(DOOR, &quot;Door opened&quot;);
logger.info(DOOR, &quot;Door closed&quot;);

Where DOOR is a constant that defines a marker, in Log4j, you do it like this:

public static final Marker DOOR = MarkerManager.getMarker(“DOOR”);

No new loggers needed, just an additional parameter to your log call, regardless of the level API used.

Now, I can configure Log4j to log only events that contain the marker DOOR (if that level is enabled). Truly awesome. In order to do this, we must use filters:

&lt;?xml version=&quot;1.0&quot; encoding=&quot;UTF-8&quot;?&gt;
&lt;Configuration status=&quot;WARN&quot; monitorInterval=&quot;5&quot;&gt;
    &lt;Console name=&quot;Console&quot; target=&quot;SYSTEM_OUT&quot; /&gt;
    &lt;Root level=&quot;WARN&quot;&gt;
      &lt;AppenderRef ref=&quot;Console&quot; /&gt;
    &lt;Logger name=&quot;com.example.oven&quot; level=&quot;DEBUG&quot; /&gt;
    &lt;Logger name=&quot;com.example.garage&quot; level=&quot;INFO&quot; /&gt;
    &lt;MarkerFilter marker=&quot;DOOR&quot; onMatch=&quot;ACCEPT&quot; onMismatch=&quot;DENY&quot; /&gt;

Here, start by setting the root logger to WARN, then we set the oven to log at DEBUG because the oven logs door events at the DEBUG level, and the garage to log at INFO because the garage logs door events at the INFO level. Next, we define filters, and here we only have one: a marker filter set to only accept DOOR markers and reject all others.

If instead, we wanted to hide DOOR events, we’d say:

&lt;MarkerFilter marker=&quot;DV.BUFFER&quot; onMatch=&quot;DENY&quot; onMismatch=&quot;NEUTRAL&quot; /&gt;

I’ve used markers for:

  • Different kinds of hex dumps:
    • Compressed buffers
    • Decompressed buffers
    • IO buffers
  • Different kinds of SQL statements:
    • Queries
    • Batches
    • Prepared statements
  • Flow tracing (built-in Log4j)
  • and more

That, my friends, is what I call Top Gun logging!


Levels tell you how important an event is. Loggers define who does the logging. Markers refine what it is you are logging. Filters let you control what ends up in your logs. If you combine these concepts with care, your applications will create logs that will help you debug, analyze, monitor and audit your applications with ease and grace.

Happy coding,
Gary Gregory

[1] DEFCON: https://en.wikipedia.org/wiki/DEFCON

Watch Maven in Color

Color TV!

Color TV!

Maven is not TV, but if I’m going to watch it, I want to see it in color.

Luckily, it’s straightforward, here’s how:

  1. Delete or backup Maven’s lib/slf4j-simple-1.7.5.jar file.
  2. Copy the following files to Maven’s lib folder:
    1. jansi-1.11.jar (if you are on Windows)
    2. The following Log4j 2 jars (where x is a version number):
      1. log4j-api-2.x.jar
      2. log4j-core-2.x.jar
      3. log4j-slf4j-impl-2.x.jar
    3. slf4j-ext-1.7.5.jar
  3. Create a log4j2.xml configuration file in Maven’s conf/logging folder.

<?xml version="1.0" encoding="UTF-8" ?>
    <Property name="maven.logging.root.level">INFO</Property>
    <Console name="console" target="SYSTEM_OUT">
      <PatternLayout pattern="%highlight{[%p] %msg%n%throwable}" />
    <Root level="${sys:maven.logging.root.level}">
      <Appender-ref ref="console"/>

This will give you output that looks like this:


The coloring is enabled in the PatternLayout with the highlight option, which gives you decent default colors for each level. You can produce a fancier layout with:

%highlight{%d [%t] %-5level: %msg%n%throwable}

In the above example. the text between %highlight{ and } is the log event template. For an explanation of the templates option, please see the Log4j manual.

You can override the default colors in the optional {style} option. For example:

%highlight{%d [%t] %-5level: %msg%n%throwable}{FATAL=white, ERROR=red, WARN=blue, INFO=black, DEBUG=green, TRACE=blue}

You can highlight only the a portion of the log event:

%d [%t] %highlight{%-5level: %msg%n%throwable}

You can style one part of the message and highlight the rest the log event:

%style{%d [%t]}{black} %highlight{%-5level: %msg%n%throwable}

Enjoy life in color!