log4j学习一：解决系统日志错位问题

这两天，开发的系统遇到了一个非常奇怪的问题，我们的前台程序会将日志时而输出到webapp.log，时而输出到其他日志文件如AlarmThreshold.log中，初看并无规律，但秉着“机器永远不会出错，出错的总是人”这一理念，试着分析原因。

log4j是java使用最为广泛的日志框架，它的使用也相对简单，通过配置appender，logger来定义日志的输出位置，输出格式等，也可以将数据输出到控制台，远程文件系统，数据库等。下面给出一个log4.xml的配置文件：

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="false" xmlns:log4j="http://jakarta.apache.org/log4j/">
<appender name="console" class="org.apache.log4j.ConsoleAppender">//控制台输出
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{hh:mm:ss.SSS}   [%t]   %p   -   %m%n"/>
</layout>
</appender>

<appender name="OptToDB" class="com.langchao.comm.logweb.OperationAppender">//自定义输出
<param name="Sql" value="%m" />
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="INFO" />
<param name="LevelMax" value="INFO" />
</filter>
</appender>

<appender name="common" class="org.apache.log4j.DailyRollingFileAppender">//滚动文件输出
<param name="File" value="${PM4H_LOG}/webapp.log"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS}   [%t]   %p   -   %m%n"/>
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="DEBUG" />
<param name="LevelMax" value="FATAL" />
</filter>
</appender>

<appender name="development" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${PM4H_LOG}/webdevelopment.log"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS}   [%t]   %p   -   %m%n"/>
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="DEBUG" />
<param name="LevelMax" value="FATAL" />
</filter>
</appender>
<!-- ============================================ new pm log =============================================== -->
<appender name="pm.web.log.debug" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${PM4H_LOG}/webapp.log" />
<param name="DatePattern" value="'.'yyyy-MM-dd" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{yyyy-MM-dd HH:mm:ss.SSS}   [%t]   %p [%X{module}-%X{lognumber}] [USER:%X{user}] [%X{class}].[%X{method}]: %m%n" />
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="DEBUG" />
<param name="LevelMax" value="DEBUG" />
</filter>
</appender>

<appender name="pm.web.log.error" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${PM4H_LOG}/webapp.log" />
<param name="DatePattern" value="'.'yyyy-MM-dd" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{yyyy-MM-dd HH:mm:ss.SSS}   [%t]   %p [%X{module}-%X{lognumber}] [USER:%X{user}] [%X{class}].[%X{method}]: %m%n" />
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="WARN" />
<param name="LevelMax" value="FATAL" />
</filter>
</appender>

<appender name="pm.web.log.info" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${PM4H_LOG}/webapp.log" />
<param name="DatePattern" value="'.'yyyy-MM-dd" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern"
value="%d{yyyy-MM-dd HH:mm:ss.SSS}   [%t]   %p [%X{module}-%X{lognumber}] [USER:%X{user}] %X{operation} %X{target} %X{target_count} %X{operation_action}: %m%n" />
</layout>
<filter class="org.apache.log4j.varia.LevelRangeFilter">
<param name="LevelMin" value="INFO" />
<param name="LevelMax" value="INFO" />
</filter>
</appender>
<!-- ==================================== end =========================================== -->
<logger name="commonLogger" additivity="false">
<level  value ="INFO"/>
<appender-ref ref="common" />
<appender-ref ref="console" />
</logger>

<logger name="developmentLogger" additivity="false">
<level  value ="INFO"/>
<appender-ref ref="common" />
<appender-ref ref="console" />
</logger>

<logger name="operationlog" additivity="false">
<level  value ="INFO"/>
<appender-ref ref="OptToDB" />
</logger>

<logger name="com.ibatis" additivity="false">
<level  value ="DEBUG"/>
<appender-ref ref="console" />
</logger>

<logger name="java.sql" additivity="false">
<level  value ="DEBUG"/>
<appender-ref ref="console" />
</logger>

<logger name="pm.web.log" additivity="false">//自定义logger，代码中可以通过Log.getLogger获取
<level  value ="DEBUG"/>
<appender-ref ref="pm.web.log.error" />
<appender-ref ref="pm.web.log.info" />
<appender-ref ref="pm.web.log.debug" />
<appender-ref ref="console" />
</logger>

<root>//默认logger,其他logger均集成此logger
<level value="INFO" />
<appender-ref ref="common" />
</root>

</log4j:configuration>

系统运行时首先会读取该配置文件初始化logger，对于rootlogger来说，通常是全局的。

经过分析，系统出现日志错误答应你的原因是，后台jar包与前台使用了不同的日志打印方式，后台程序在拿不到指定logger后，会使用root节点配置的appender，最过分的是，私有实现竟在代码中修改了appender指向的File，这种流氓似得行径给定位问题带来了巨大困难，与发射类似，运行时修改代码的成本太高了。

原因找到之后，剩下的就简单了，在重定向逻辑中加入判断是否是前后台分别处理，即可。