Peter V. Mørch
Peter V. Mørch

Reputation: 15907

How to catch errors during log4j2 initialization?

We don't consider our app running properly if log4j2 isn't configured properly as specified in the config file. How do i reliably detect whether errors have occurred during log4j2 initialization and been printed on the console from java? There are (at least) two sources of bad configuration:

  1. The configuration file is entirely missing (or invalid?)
  2. The configuration file is valid, but has a problem during setConfiguration().

This question is about the second point. It looks like log4j2 internally does try{...} catch(e) { LOGGER.error("bla bla", e) } during initialization making it impossible to detect such problems.

Errors printed to the console that no human is ever going to see is bad. We'd rather have our app crash!

I'm surprised that I can't find a way to programmatically ask log4j2: "Did I get the configuration I asked for?". Is there something I have overlooked? E.g. some way to detect whether anything has been logged yet?

Background

Here is the console output we're seeing. Yes, there is permission denied to /path/to/file - how do I detect that?

2015-10-15 17:43:50,539 main ERROR FileManager (/path/to/file) java.io.FileNotFoundException: /path/to/file (Permission denied)
2015-10-15 17:43:50,541 main ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.FileAppender for element File. java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:136)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:794)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:734)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:726)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:383)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:161)
        at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:173)
        at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:422)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:494)
        at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:510)
        at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:199)
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:146)
        at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:41)
        at org.apache.logging.log4j.LogManager.getContext(LogManager.java:177)
        at org.apache.logging.log4j.LogManager.getLogger(LogManager.java:447)
        at (our first call to org.apache.logging.log4j.LogManager.getLogger())

Looking in the code for LoggerContext.reconfigure(), I see:

private void reconfigure(final URI configURI) {
    <snip>
    final Configuration instance = ConfigurationFactory.getInstance().getConfiguration(name, configURI, cl);
    setConfiguration(instance);
    <snip>
}

And during the call of setConfiguration(), there is this in org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build:

    try {
        <snip>
        final Object plugin = factory.invoke(null, params);
        <snip>
        return plugin;
    } catch (final Exception e) {
        LOGGER.error("Unable to invoke factory method in class {} for element {}.", this.clazz, this.node.getName(),
            e);
        return null;
    }

So the problem was not with getConfiguration() from the ConfigurationFactory, but with the subsequent setConfiguration(), and there seems to be no way to detect that there was a problem... :-(

About the first point: The configuration file is entirely missing (or invalid?)

We're setting -Dlog4j.configurationFile=<file> on the java command line, and there are already several posts on how to detect if <file> is missing. One of which suggests to -Dlog4j.configurationFactory with our own ConfigurationFactory. But no amount of fiddling with our own ConfigurationFactory is going to help during setConfiguration() to detect the second point ("2." above) as far as I can reason.

We're running log4j2 version 2.4 on openjdk 8 on debian stable/jessie.

Upvotes: 2

Views: 1630

Answers (1)

Peter V. M&#248;rch
Peter V. M&#248;rch

Reputation: 15907

It turns out the Log4j2 internals use a special StatusLogger, that has a getStatusData() method, so here's what to do:

    import org.apache.logging.log4j.status.StatusData;
    import org.apache.logging.log4j.status.StatusLogger;
    ...
    StatusLogger statusLogger = StatusLogger.getLogger();
    if (statusLogger.getStatusData().size() > 0) {
        System.out.printf(
                "Logged %d messages\n",
                statusLogger.getStatusData().size()
            );
        // Investigate List<StatusData> if you want
        for(StatusData data : statusLogger.getStatusData()) {
            System.out.printf(
                    "    Level %s message: %s\n",
                    data.getLevel(),
                    data.getMessage().getFormattedMessage()
                );
        }
        System.err.println("exiting due to unexpected console status logs");
        System.exit(1);
    }

Upvotes: 2

Related Questions