Search code examples
javalog4japache-stormlog4j2

Apache Storm - log4j2 is printing its own log all the time even I turn off the root logger

In my Storm APP, every time I run I now get these lines from console:

2018-01-17 18:38:30,417 main DEBUG Initializing configuration XmlConfiguration[location=D:\Desarrollo\workspaces\oxygen_main\StormAcustat\target\classes\log4j2.xml]
2018-01-17 18:38:30,426 main DEBUG Installed script engines
2018-01-17 18:38:31,172 main DEBUG Oracle Nashorn Version: 1.8.0_144, Language: ECMAScript, Threading: Not Thread Safe, Compile: true, Names: {nashorn, Nashorn, js, JS, JavaScript, javascript, ECMAScript, ecmascript}
2018-01-17 18:38:31,172 main DEBUG PluginManager 'Core' found 112 plugins
2018-01-17 18:38:31,173 main DEBUG PluginManager 'Level' found 0 plugins
2018-01-17 18:38:31,185 main DEBUG PluginManager 'Lookup' found 13 plugins
2018-01-17 18:38:31,189 main DEBUG Building Plugin[name=layout, class=org.apache.logging.log4j.core.layout.PatternLayout].
2018-01-17 18:38:31,214 main DEBUG PluginManager 'TypeConverter' found 26 plugins
2018-01-17 18:38:31,255 main DEBUG PatternLayout$Builder(pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n", PatternSelector=null, Configuration(D:\Desarrollo\workspaces\oxygen_main\StormAcustat\target\classes\log4j2.xml), Replace=null, charset="null", alwaysWriteExceptions="null", disableAnsi="null", noConsoleNoAnsi="null", header="null", footer="null")
2018-01-17 18:38:31,255 main DEBUG PluginManager 'Converter' found 41 plugins
2018-01-17 18:38:31,259 main DEBUG Building Plugin[name=appender, class=org.apache.logging.log4j.core.appender.ConsoleAppender].
2018-01-17 18:38:31,282 main DEBUG ConsoleAppender$Builder(target="SYSTEM_OUT", follow="null", direct="null", bufferedIo="null", bufferSize="null", immediateFlush="null", ignoreExceptions="null", PatternLayout(%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n), name="Console", Configuration(D:\Desarrollo\workspaces\oxygen_main\StormAcustat\target\classes\log4j2.xml), Filter=null)
2018-01-17 18:38:31,283 main DEBUG Jansi is not installed, cannot find org.fusesource.jansi.WindowsAnsiOutputStream
2018-01-17 18:38:31,284 main DEBUG Starting OutputStreamManager SYSTEM_OUT.false.false

I have configured the log4j2.xml to make Storm redirect its log into different log files, and it is working:

<Loggers>
        <Logger name="org.apache.storm" level="debug" additivity="false">
            <AppenderRef ref="Storm"/>
        </Logger>
        <Logger name="org.apache.storm.kafka" level="debug" additivity="false">
            <AppenderRef ref="Storm-Kafka"/>
        </Logger>
        <Logger name="org.apache.zookeeper" level="debug" additivity="false">
            <AppenderRef ref="ZooKeeper"/>
        </Logger>
        <Logger name="org.apache.storm.shade.org.apache.zookeeper" level="debug" additivity="false">
            <AppenderRef ref="Storm-ZooKeeper"/>
        </Logger>
        <Logger name="TestMain" level="info">
            <AppenderRef ref="TestMain"/>
        </Logger>
        <!-- these lines don't work -->
        <Logger name="org.apache.logging.log4j" level="info">
            <AppenderRef ref="Storm-logging"/> 
        </Logger>
        <Root level="OFF">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>

But I still get these logs from the console. I want to eliminate it with log4j or log4j2 configuration.

I have checked the logs, and seeing that these logs seem to come from org.apache.logging.log4j itself, not from any other Storm classes, because the log files of org.apache.storm, org.apache.storm.kafka and so on, don't include these lines, and checking the source code, PluginManager {} found {} plugins is seen in the class:

org.apache.logging.log4j.core.config.plugins.util.PluginManager.class

It is inside one of the dependency, log4j-core-2.8.2.jar.

So, it seems that the console prints the logs from log4j, not from Storm.

How to prevent that? As you can see, I have turned off root logger and I have these lines, but they don't work:

<Logger name="org.apache.logging.log4j" level="info">
    <AppenderRef ref="Storm-logging"/> 
</Logger>

EDIT: My log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        </Console>
        <RollingFile name="TestMain" fileName="D:\Proyectos\Storm\test\TestMain.log" filePattern="D:\Proyectos\Storm\test\TestMain.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
        <RollingFile name="Storm" fileName="D:\Proyectos\Storm\test\Storm.log" filePattern="D:\Proyectos\Storm\test\Storm.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
        <RollingFile name="Storm-Kafka" fileName="D:\Proyectos\Storm\test\Storm-Kafka.log" filePattern="D:\Proyectos\Storm\test\Storm-Kafka.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
        <RollingFile name="ZooKeeper" fileName="D:\Proyectos\Storm\test\ZooKeeper.log" filePattern="D:\Proyectos\Storm\test\ZooKeeper.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
        <RollingFile name="Storm-ZooKeeper" fileName="D:\Proyectos\Storm\test\Storm-ZooKeeper.log" filePattern="D:\Proyectos\Storm\test\Storm-ZooKeeper.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
        <RollingFile name="Storm-logging" fileName="D:\Proyectos\Storm\test\Storm-logging.log" filePattern="D:\Proyectos\Storm\test\Storm-logging.%d{yyyy-MM-dd}.log"
            bufferedIO="true" immediateFlush="true" append="true" ignoreExceptions="false"> <!-- bufferedIO: large performance improvement -->
            <PatternLayout pattern="%d{yyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="org.apache.storm" level="debug" additivity="false">
            <AppenderRef ref="Storm"/>
        </Logger>
        <Logger name="org.apache.storm.kafka" level="debug" additivity="false">
            <AppenderRef ref="Storm-Kafka"/>
        </Logger>
        <Logger name="org.apache.zookeeper" level="debug" additivity="false">
            <AppenderRef ref="ZooKeeper"/>
        </Logger>
        <Logger name="org.apache.storm.shade.org.apache.zookeeper" level="debug" additivity="false">
            <AppenderRef ref="Storm-ZooKeeper"/>
        </Logger>
        <Logger name="TestMain" level="info">
            <AppenderRef ref="TestMain"/>
        </Logger>
        <Logger name="org.apache.logging.log4j" level="info">
            <AppenderRef ref="Storm-logging"/>
        </Logger>
        <Root level="OFF">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>
Solution

  • The logs that are getting printed are of log4j2 because you have enabled debug level logging of log4j2.

    To turn off this detailed logging, change status attribute of Configuration element in your configuration to warn or error -

    <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
    <Appenders>
...

    Rest should remain same.

    Log4j2 documentation describes about this logging in detail -

    From log4j-2.9 onward

    From log4j-2.9 onward, log4j2 will print all internal logging to the console if system property log4j2.debug is defined (with any or no value).

    Prior to log4j-2.9

    Prior to log4j-2.9, there are two places where internal logging can be controlled:

    If the configuration file is found correctly, log4j2 internal status logging can be controlled by setting <Configuration status="trace"> in the configuration file. This will display detailed log4j2-internal log statements on the console about what happens during the configuration process. This may be useful to trouble-shoot configuration issues. By default the status logger level is WARN, so you only see notifications when there is a problem.

    If the configuration file is not found correctly, you can still enable log4j2 internal status logging by setting system property -Dorg.apache.logging.log4j.simplelog.StatusLogger.level=TRACE.