Category Archives: Log4j

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;

    @PostConstruct
    @TransactionAttribute(value=TransactionAttributeType.NOT_SUPPORTED)
    private void postConstruct() {
        logctx = Configurator.initialize(LOGGER_CONTEXT_NAME, LOGGER_CONFIG);
        logger = logctx.getLogger("com.whatever.myejb");
    }

    @PreDestroy
    @TransactionAttribute(value=TransactionAttributeType.NOT_SUPPORTED)
    private void preDestroy() {
        Configurator.shutdown(logctx);
    }
}

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!
Gary

 

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);
Configurator.setLevel(map);

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)).

Configurator.setRootLevel(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: An exploration with Apache Log4j 2

I’ll be giving my talk “The Art of Logging: An exploration with Apache Log4j 2” at the South Bay Java User’s Group, Thursday, November 19, 2015 at 6:30 PM. Come check it out if you are in the area! For more details, please visit http://www.meetup.com/South-Bay-JVM-User-Group/events/226362027/

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