Black House

log4j MDC 用户操作日志追踪配置

7/13/2017 log

log MDC 的使用

MDC 介绍

MDC（Mapped Diagnostic Context, 映射调试上下文）是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能. 某些应用程序采用多线程的方式来处理多个用户的请求. 在一个用户的使用过程中, 可能有多个不同的线程来进行处理. 典型的例子是 Web 应用服务器. 当用户访问某个页面时, 应用服务器可能会创建一个新的线程来处理该请求, 也可能从线程池中复用已有的线程. 在一个用户的会话存续期间, 可能有多个线程处理过该用户的请求. 这使得比较难以区分不同用户所对应的日志. 当需要追踪某个用户在系统中的相关日志记录时, 就会变得很麻烦.

一种解决的办法是采用自定义的日志格式, 把用户的信息采用某种方式编码在日志记录中. 这种方式的问题在于要求在每个使用日志记录器的类中, 都可以访问到用户相关的信息. 这样才可能在记录日志时使用. 这样的条件通常是比较难以满足的. MDC 的作用是解决这个问题.

MDC 可以看成是一个与当前线程绑定的哈希表, 可以往其中添加键值对. MDC 中包含的内容可以被同一线程中执行的代码所访问. 当前线程的子线程会继承其父线程中的 MDC 的内容. 当需要记录日志时, 只需要从 MDC 中获取所需的信息即可. MDC 的内容则由程序在适当的时候保存进去. 对于一个 Web 应用来说, 通常是在请求被处理的最开始保存这些数据.

MDC 使用案例

相对比较大的项目来说, 一般会有多个开发人员, 如果每个开发人员凭自己的理解打印日志, 那么当用户反馈问题时, 很难通过日志去快速的定位到出错原因, 也会消耗更多的时间. 所以针对这种问题, 一般会定义好整个项目的日志格式, 如果是需要追踪的日志, 开发人员调用统一的打印方法, 在日志配置文件里面定义好相应的字段, 通过 MDC 功能就能很好的解决问题.

比如我们可以事先把用户的 sessionId, 登录用户的用户名, 访问的城市 id, 当前访问商户 id 等信息定义成字段, 线程开始时把值放入 MDC 里面, 后续在其他地方就能直接使用, 无需再去设置了.

使用 MDC 来记录日志, 一来可以规范多开发下日志格式的一致性, 二来可以为后续使用 ELK 对日志进行分析.

所需依赖

<dependency>  
  <groupId>log4j</groupId>  
  <artifactId>log4j</artifactId>  
  <version>1.2.17</version>  
</dependency>  
<dependency>  
    <groupId>org.slf4j</groupId>  
    <artifactId>slf4j-log4j12</artifactId>  
    <version>1.7.21</version>  
</dependency>
1
2
3
4
5
6
7
8
9
10

log4j.xml 配置样例, 追踪日志自定义格式主要在 name="trance" 的 layout 里面进行设置, 我们使用 %X{userName} 来定义此处会打印 MDC 里面 key 为 userName 的 value, 如果所定义的字段在 MDC 不存在对应的 key, 那么将不会打印, 会留一个占位符.

<?xml version="1.0" encoding="UTF-8"?>  
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">  
<log4j:configuration>  
    <appender name="console" class="org.apache.log4j.ConsoleAppender">  
        <param name="target" value="System.out" />  
        <layout class="org.apache.log4j.PatternLayout">  
            <param name="ConversionPattern" value="%-d{yyyy-MM-dd HH:mm:ss.SSS} %-6p%c:%L %x - %m%n" />  
        </layout>  
    </appender>  
  
    <appender name="error" class="org.apache.log4j.DailyRollingFileAppender">  
        <param name="File" value="D://logs//error.log" />  
        <param name="DatePattern" value="'.'yyyy-MM-dd" />  
        <param name="threshold" value="error"/>  
        <param name="append" value="true"/>  
        <layout class="org.apache.log4j.PatternLayout">  
            <param name="ConversionPattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-6p%c:%L - %m%n" />  
        </layout>  
    </appender>  
  
    <appender name="logic" class="org.apache.log4j.DailyRollingFileAppender">  
        <param name="File" value="D://logs//logic.log" />  
        <param name="DatePattern" value="'.'yyyy-MM-dd" />  
        <param name="threshold" value="info"/>  
        <param name="append" value="true"/>  
        <layout class="org.apache.log4j.PatternLayout">  
            <param name="ConversionPattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-6p%c:%L - %m%n" />  
        </layout>  
    </appender>  
  
    <appender name="trace" class="org.apache.log4j.DailyRollingFileAppender">  
        <param name="File" value="D://logs//trace.log" />  
        <param name="DatePattern" value="'.'yyyy-MM-dd" />  
        <param name="threshold" value="info"/>  
        <param name="append" value="true"/>  
        <layout class="org.apache.log4j.PatternLayout">  
               <param name="ConversionPattern" value="[%d{yyyy-MM-dd HH:mm:ss.SSS}] - %X{mchId} - %X{mchName} - %X{siteName} - %X{sessionId} - %X{cityId} - %X{userName} - %X{mobile} - %m%n" />  
         </layout>  
    </appender>  
  
    <logger name="traceLog" additivity="false">  
        <level value="info" />  
        <appender-ref ref="trace" />  
    </logger>  
  
    <root>  
        <level value="info" />  
        <appender-ref ref="console"/>  
        <appender-ref ref="logic" />  
        <appender-ref ref="error" />  
    </root>  
</log4j:configuration>
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52

日志打印类

import org.slf4j.Logger;  
import org.slf4j.LoggerFactory;  
  
public class TraceLogger {  
    // 此处的 "tranceLog" 为 log4j 中定义的对应的 logger 的 name  
    private static final Logger TRACE_LOGGER = LoggerFactory.getLogger("traceLog");  
  
    private TraceLogger() {  
          
    }  
    
    public static void info(String message){  
        TRACE_LOGGER.info(message);  
    }  
  
    public static void info(String format,Object... arguments){  
        TRACE_LOGGER.info(format, arguments);  
    }  
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

最后写个日志打印测试一下效果

@Test  
public void Test(){  
    MDC.clear();  
    MDC.put("sessionId" , "f9e287fad9e84cff8b2c2f2ed92adbe6");  
    MDC.put("cityId" , 1);  
    MDC.put("siteName" , "北京");  
    MDC.put("userName" , "userwyh");  
    TraceLogger. info("测试 MDC 打印一");  
           
    MDC.put("mobile" , "110");  
    TraceLogger. info("测试 MDC 打印二");  
           
    MDC.put("mchId" , 12);  
    MDC.put("mchName", "商户名称");  
    TraceLogger. info("测试 MDC 打印三");  
           
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

执行完后我们可以在定义的日志输出路径下看到以下输出

[2016-10-19 19:20:26.564] -  -  - 北京 - f9e287fad9e84cff8b2c2f2ed92adbe6 - 1 - userwyh -  - 测试 MDC 打印一  
[2016-10-19 19:20:26.565] -  -  - 北京 - f9e287fad9e84cff8b2c2f2ed92adbe6 - 1 - userwyh - 110 - 测试 MDC 打印二  
[2016-10-19 19:20:26.565] - 12 - 商户名称 - 北京 - f9e287fad9e84cff8b2c2f2ed92adbe6 - 1 - userwyh - 110 - 测试 MDC 打印三
1
2
3
Last Updated: 7/3/2019, 6:17:56 PM