log4j日志

日志

在工作过程中，编码是构建一个项目的开始，而日志记录则是维护一个项目的基石。如果一个项目中，没有完善的日志记录，那么这个项目则会有以下缺陷：

  1. 项目没有报错检测机制
  2. 项目出现系统错误时无法查找问题

现有的一些系统监测平台，都是通过获取项目的日志来进行错误报警，提示开发人员及时解决系统存在的问题。如果出现问题，需要通过记录下来的日志来记录错误信息以及上下文信息，这样可以有效及时的锁定错误。

因此，日志记录对一个项目来说是非常重要的。

我在工作过程中，也时刻想着如何记录日志，才能快速定位问题。在实践过程中，我使用三层的日志记录：

  1. Controller层使用拦截器，拦截所有用户操作请求，记录用户行为和参数。这个通常是为了审计需要记录的审计日志。
  2. Service层使用Spring AOP功能对所有方法进行切片日志记录。主要是三个切面，方法进入前、进入后、报错时，分别记录方法的参数、返回结果和错误信息。
  3. 针对每处业务处理代码中，记录错误或者报警日志。这些日志常常为正常业务处理中遇到的可预知的错误，比如方法的参数不正确，用户的信息未找到等信息。

通过这三层日志，可以全方位的记录用户在使用平台的过程中，操作的什么内容，输入了什么信息，查询到了什么结果，如果发生异常情况，异常信息是什么，在哪里发生的等等。。。

我们都知道日志一般不能只打印到工作台中，还需要记录到日志文件中，那么应该如何在工具层面把日志记录下来呢。这是本篇的重点。

正文之前，先说下这片博文的起源。我在系统开发过程中，遇到了一个很奇怪的问题。系统在测试环境中，为了方面测试功能数据权限，我们加了一个切换session的功能。这样可以方便测试人员，切换不能角色来看数据权限和功能权限。但是呢，在切换的过程中，发现人员的数据权限不正确，跟预想的不同。排除了代码bug的情况下，思考可能是session切换有问题，但是通过查询日志发现，session确实切到了正确的人，那为什么查询结果不正确呢。我请教了我的导师，我的导师建议我去查一下mybatis执行sql日志。但是怎么才能输出mybatis执行的sql日志呢？下面就是正文了。

以log4j为例，我们需要记录系统中不同模块日志到不同的文件中。那么日志的配置应该是这样的：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">
    <!-- 全局配置 -->
    <root>
        <priority value="INFO" />
        <appender-ref ref="Console" />
    </root>
    <logger name="saLog" additivity="false">
        <level value="DEBUG"/>
        <appender-ref ref="saLogAppender"/>
    </logger>
    <appender name="saLogAppender" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="/home/xiaoju/soc-logs/soc-web/soc-web-sa.log" />
        <param name="DatePattern" value="'.'yyyy-MM-dd" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%p] %d{yyyy-MM-dd HH:mm:ss} %C.%M : %m%n%x" />
        </layout>
    </appender>
</log4j:configuration>

这是基础的log4j配置。在以前我只知道这么用，但是没有想过这么配的原理是什么。不知道原理的话，在遇到新的问题时就会不知所措，就像现在我想知道如何打印mybatis的执行日志到日志文件中。

先说这个问题的答案吧，有两种方式：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
<root>
    <priority value="DEBUG" />
    <appender-ref ref="Console" />
</root>
<logger name="org.apache.ibatis" additivity="false">
    <level value="DEBUG" />
</logger>
 
<logger name="java.sql.Connection" additivity="false">
    <level value="DEBUG"/>
</logger>
<logger name="java.sql.Statement" additivity="false">
    <level value="DEBUG" />
</logger>
<logger name="java.sql.PreparedStatement" additivity="false">
    <level value="DEBUG" />
</logger>

这样项目中所有的mybatis执行sql都会被打印出来，但是这种方式必须要求rootLogger的level是debug。至于为什么需要debug，我也不知道，网上也找不到答案。

另外一种是更有针对性的：

1
2
3
<logger name="com.didichuxing.dao.sa.AssessmentMapper">
    <level value="DEBUG" />
</logger>

这样只要这个Mapper执行，就会把sql打印出来。

那么为什么可以这样配置呢？从上面的logger name其实我们能看出来，这个其实就是类名或者包名。所以log4j的日志配置是可以根据类名或者包名来进行定位的，如果一个类打印了日志，那么可以从配置中找其对应的类或者包配置，然后再根据appender将日志信息记录到工作台或者文件中。当然我们也可以单独定义logger name，然后使用这个logger来进行日志打印。

除此之外，logger是有继承关系的。继承的原理就是根据name来排出上下级。比如一个com.hello.HelloWorld的类打印日志，那么首先会寻找有没有名称为com.hello.HelloWorld的logger配置，如果没有则会找com.hello的logger配置，然后找com的logger配置，最后达到rootLogger。所以日志打印会根据这个继承链从下往上传递日志信息。但是我们不想重复打印这么多次怎么办，使用additivity，设置为false就不会把日志向上传递了。

另外一个需要注意的是日志的打印等级。log4j一共有OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、ALL 8种，等级依次降低。logger设置了等级之后，则只会记录高于这个等级的日志。如果logger设置为INFO等级，那么所有DEBUG、TRACE、ALL的日志都不会记录。

从这次不知道怎么打印mybatis的执行sql，学到了怎么设置打印sql，logger设置的原理是什么，日志分发的机制是什么，日志级别的作用，以及logger的继承关系。