Kristof Kristof - 1 year ago 108
Java Question

log4j logs everything regardless of the root level

We have some standalone java applications that log information to log files, with log4j (it's an old version : 1.2.8).

We have set the root level to ERROR, and defined several appenders, depending on the calling module.

The odd thing is that everything is logged, regardless of the level (INFO, DEBUG, etc.). We then decided to add the -Dlog4j.debug option to the java command line to find out if there wasn't a faulty log4.xml file being loaded, and then we saw this :

log4j: Trying to find [log4j.xml] using context classloader sun.misc.Launcher$AppClassLoader@64c3c749.
log4j: Trying to find [log4j.xml] using sun.misc.Launcher$AppClassLoader@64c3c749 class loader.
log4j: Trying to find [log4j.xml] using ClassLoader.getSystemResource().
log4j: Trying to find [log4j.properties] using context classloader sun.misc.Launcher$AppClassLoader@64c3c749.
log4j: Trying to find [log4j.properties] using sun.misc.Launcher$AppClassLoader@64c3c749 class loader.
log4j: Trying to find [log4j.properties] using ClassLoader.getSystemResource().
log4j: Could not find resource: [null].


Why does log4j log everything, even if the root level is set to ERROR, and how can the configuration be loaded while it seems that it cannot be found?

EDIT :

1) Yes, everything is logged to the correct appenders, with the correct format and file names.

2) The log4j.xml is inside a jar, specified in the classpath.

Here is the log4j.xml:




<!-- Definition des appenders par niveau de log -->
<appender name="all" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_ALL.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="ERROR"/>
</filter>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="debug" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_DEBUG.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="DEBUG"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="info" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_INFO.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="INFO"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="warn" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_WARN.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="WARN"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="error" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_ERROR.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="ERROR"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="fatal" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010_FATAL.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelToMatch" value="FATAL"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<!-- Definition des appenders specifiques -->
<!-- MVNO 2012 -->
<appender name="mvno2012" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_MVNO2012.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %t | %L | %m%n" />
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
</appender>

<!-- Moteur de collecte -->
<appender name="engine_collecte" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_COLLECTE_ENGINE.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %t | %L | %m%n" />
</layout>
</appender>

<!-- Utilitaires apache (org.apache ...) -->
<appender name="apache_utilities" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_APACHE_UTILITIES.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelMatchFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>



<appender name="aruba" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARUBA.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="fx" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_FX.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<filter class="org.apache.log4j.varia.DenyAllFilter"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="tuxedo" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_TUXEDO.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c | %L | %m%n" />
</layout>
</appender>

<appender name="arbor2010" class="org.apache.log4j.RollingFileAppender">
<param name="file" value="${REP_LOG_OPE}/CA_ARBOR2010.log"/>
<param name="Append" value="true"/>
<param name="MaxFileSize" value="80000KB"/>
<param name="MaxBackupIndex" value="2000"/>
<layout class="org.apache.log4j.SimpleLayout"/>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="levelMin" value="DEBUG"/>
<param name="levelMax" value="FATAL"/>
</filter>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{dd/MM/yy - HH:mm:ss,SSS} | %-1p | %c{1} | %L | %X{ID} | %m%n" />
</layout>
</appender>

<logger name="com.ours.theirs.arbor2010" additivity="false">
<appender-ref ref="arbor2010"/>
</logger>

<logger name="com.ours.theirs.mvno2012" additivity="false">
<appender-ref ref="mvno2012"/>
</logger>

<logger name="com.csgsystems" additivity="false">
<appender-ref ref="aruba"/>
</logger>

<logger name="terrapin" additivity="false">
<appender-ref ref="tuxedo"/>
</logger>

<logger name="com.csgsystems.fx" additivity="false">
<appender-ref ref="fx"/>
</logger>

<logger name="com.ours.collecte" additivity="true">
<appender-ref ref="engine_collecte"/>
</logger>

<logger name="com.ours.common" additivity="false">
<appender-ref ref="engine_collecte"/>
</logger>

<logger name="org.apache" additivity="false">
<appender-ref ref="apache_utilities"/>
</logger>

<root>
<level value="ERROR"/>
<appender-ref ref="all"/>
</root>




EDIT 2 :

I still haven't found what's happening, but here is what I have found out and done so far :

1) The log4j.xml file was malformed : it was missing the DOCTYPE, there were multiple layouts, some layout classes were incorrect.

2) I have specified the path to the log4j.xml file in the command line
3) There were several calls to DOMConfigurator and PropertyConfigurator, I've removed them.

I have narrowed my research to a class that creates dynamic log files based on a thread id. Before the code in that class is executed, the log4j console logs clearly states the log level is ERROR. The moment the dynamic log files are created, the log level switches to DEBUG.

The answer is near.

EDIT 3

I've found the culprit!

A third party component loads its own log4j configuration on top of ours. It adds appenders and it changes the root logging level.

It's good to note that when a new file is loaded, log4j doesn't seem to debug that information to the console.

Answer Source

The root level was changed by a third party component, which loads a specific configuration.

When facing such a problem :

1) Check if your code doesn't contain any extra log4j dynamic configuration loading (DOMConfigurator, PropertyConfigurator) 2) Check if any third party component doesn't load any extra log4j configuration 3) Make sure your log4j.xml (or log4j.properties) is valid.

Recommended from our users: Dynamic Network Monitoring from WhatsUp Gold from IPSwitch. Free Download