使用log4j 的NDC记录贯穿整个请求的唯一logId

记录log日志的时候，没有一条贯穿该请求的logId，

所以在linux系统中，查询某个请求的logId时，找到该请求的分界线，很困难。

比如下面的日志，有两个请求的日志，看得眼睛都花了。

<INFO><2015-10-30 08:57:19><ResourceSearchFromDBServlet> start time：20151030085719818 
<INFO><2015-10-30 08:57:19><ResourceSearchFromDBServlet> RAS接入get查询上送：TRANSTYPE=071&forins=0899999999&cardno=11111111111111111
<INFO><2015-10-30 08:57:27><CardInfoForAuthenticationDBDaoImpl> 目前的数据源是 :AuthenticationDS 
<INFO><2015-10-30 08:57:28><CardInfoForAuthenticationDBDaoImpl> 从AuthenticationDS 查询到 【1】 条记录 
<INFO><2015-10-30 08:57:28><CardInfoForCardInfoDBDaoImpl> 目前的数据源是 :CardInfoDS 
<INFO><2015-10-30 08:57:29><CardInfoForCardInfoDBDaoImpl> 从CardInfoDS 查询到 【0】 条记录 
<INFO><2015-10-30 08:57:29><CardInfoForVfwdauthDBDaoImpl> 目前的数据源是 :VfwdauthDS 
<INFO><2015-10-30 08:57:29><CardInfoForVfwdauthDBDaoImpl> 从VfwdauthDS 查询到 【2】 条记录 
<INFO><2015-10-30 08:57:29><ResourceSearchFromDBServlet> RAS查询返回：{"cardno":"11111111111111111","retcode":"0000","retmsg":"success","username":"aaaa"} 
<INFO><2015-10-30 08:57:29><ResourceSearchFromDBServlet> end time :20151030085729900 
<INFO><2015-10-30 08:57:29><ResourceSearchFromDBServlet> 请求耗时 :10.084秒 
<INFO><2015-10-30 08:58:19><ResourceSearchFromDBServlet> start time：20151030085719818 
<INFO><2015-10-30 08:58:19><ResourceSearchFromDBServlet> RAS接入get查询上送：TRANSTYPE=071&forins=0899999999&cardno=2222222222
<INFO><2015-10-30 08:58:27><CardInfoForAuthenticationDBDaoImpl> 目前的数据源是 :AuthenticationDS 
<INFO><2015-10-30 08:58:28><CardInfoForAuthenticationDBDaoImpl> 从AuthenticationDS 查询到 【1】 条记录 
<INFO><2015-10-30 08:58:28><CardInfoForCardInfoDBDaoImpl> 目前的数据源是 :CardInfoDS 
<INFO><2015-10-30 08:58:29><CardInfoForCardInfoDBDaoImpl> 从CardInfoDS 查询到 【0】 条记录 
<INFO><2015-10-30 08:58:29><CardInfoForVfwdauthDBDaoImpl> 目前的数据源是 :VfwdauthDS 
<INFO><2015-10-30 08:58:29><CardInfoForVfwdauthDBDaoImpl> 从VfwdauthDS 查询到 【2】 条记录 
<INFO><2015-10-30 08:58:29><ResourceSearchFromDBServlet> RAS查询返回：{"cardno":"2222222222","retcode":"0000","retmsg":"success","username":"bbbbb"} 
<INFO><2015-10-30 08:58:29><ResourceSearchFromDBServlet> end time :20151030085729900 
<INFO><2015-10-30 08:58:29><ResourceSearchFromDBServlet> 请求耗时 :10.084秒 

发现log4j中有一个NDC的类，可以很方便的贯穿整个log日志的记录

下面详细了解一下log4j的NDC

NDC（Nested Diagnostic Context）是 Neil Harrison 在名为《 Patterns for Logging Diagnostic Messages 》的书中提出的嵌套诊断环境的机制。这种机制的提出，主要为了减少多线程的系统为每个客户单独记录日志的系统开销。在过去，区分两个客户的日志输出的常用方法是单独为每个客户机实例化新类别，但该方法会增加类别数量，并增加日志记录的管理开销。Neil Harrison 提出的方法就是把用户的上下文信息放到嵌套式诊断环境 (NDC) 中。

NDC 为每一个线程管理一个堆栈。开发人员可以在代码中合适的位置嵌入简单的 push 和 pop 方法，用来维护堆栈。通常 push 进堆栈的是可以唯一标示客户的上下文信息，如 SessionID 或者客户名称，IP 地址等。因为每个客户请求都会有单独的 NDC 堆栈，因此日志系统在输出的时候会根据每个线程找到对应的堆栈，并在输出日志的时候附加上堆栈内的信息。开发人员就可以很容易的在日志中区分出各个不同客户所产生的日志条目。

NDC里面有如下几个方法

 public class NDC { 
    // 返回诊断堆栈的内容
    public static String get(); 
    // 从堆栈的顶端删除一个元素
    public static String pop(); 
    // 在堆栈顶端加入一个元素
    public static void push(String message); 
    // 察看这个堆栈最顶层的元素，但不删除它
    public static String peek() 
    // 删除这个线程的堆栈内容
    public static void remove(); 
 }

调用时，只需要

String logId = System.currentTimeMillis();
NDC.push(logId);

日志的结尾，别忘了调用remove，否则logId会一直叠加

NDC.remove();

同时，log4j.properties配置为%x

log4j.rootLogger=DEBUG,A1,D

#################################################################################################
####################################### Console #################################################
#################################################################################################
# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.encoding=GBK
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=[%x]<%p><%-d{yyyy-MM-dd HH:mm:ss}><%c{1}> <%m>%n

#################################################################################################
############################################ detail ###############################################
#################################################################################################
log4j.appender.D=org.apache.log4j.DailyRollingFileAppender
log4j.appender.D.encoding=GBK
log4j.appender.D.Threshold=INFO
log4j.appender.D.File=E:/log/ras/detail
log4j.appender.D.DatePattern='.'yyyy-MM-dd
log4j.appender.D.layout=org.apache.log4j.PatternLayout
log4j.appender.D.layout.ConversionPattern=<%x><%-d{HH:mm:ss}><%c{1}> %m %n

可以测试看看日志

<20151030110959096><11:09:59><ResourceSearchFromDBServlet> start time：20151030110959096 
<20151030110959096><11:09:59><ResourceSearchFromDBServlet> RAS接入get查询上送：TRANSTYPE=071&forins=0899999999&cardno=1111111
<20151030110959096><11:10:06><CardInfoForAuthenticationDBDaoImpl> 目前的数据源是 :AuthenticationDS 
<20151030110959096><11:10:07><CardInfoForAuthenticationDBDaoImpl> 从AuthenticationDS 查询到 【1】 条记录 
<20151030110959096><11:10:07><CardInfoForCardInfoDBDaoImpl> 目前的数据源是 :CardInfoDS 
<20151030110959096><11:10:07><CardInfoForCardInfoDBDaoImpl> 从CardInfoDS 查询到 【0】 条记录 
<20151030110959096><11:10:07><CardInfoForVfwdauthDBDaoImpl> 目前的数据源是 :VfwdauthDS 
<20151030110959096><11:10:08><CardInfoForVfwdauthDBDaoImpl> 从VfwdauthDS 查询到 【2】 条记录 
<20151030110959096><11:10:08><ResourceSearchFromDBServlet> [20151030110959096]RAS查询返回：{"cardno":"1111111","retcode":"0000","retmsg":"success","username":"aaaa"} 
<20151030110959096><11:10:08><ResourceSearchFromDBServlet> end time :20151030111008614 
<20151030110959096><11:10:08><ResourceSearchFromDBServlet> 请求耗时 :49.52秒 
<20151030111035240><11:10:35><ResourceSearchFromDBServlet> start time：20151030111035240 
<20151030111035240><11:10:35><ResourceSearchFromDBServlet> RAS接入get查询上送：TRANSTYPE=071&forins=0899999999&cardno=222222
<20151030111035240><11:10:35><CardInfoForAuthenticationDBDaoImpl> 目前的数据源是 :AuthenticationDS 
<20151030111035240><11:10:35><CardInfoForAuthenticationDBDaoImpl> 从AuthenticationDS 查询到 【1】 条记录 
<20151030111035240><11:10:35><CardInfoForCardInfoDBDaoImpl> 目前的数据源是 :CardInfoDS 
<20151030111035240><11:10:35><CardInfoForCardInfoDBDaoImpl> 从CardInfoDS 查询到 【0】 条记录 
<20151030111035240><11:10:35><CardInfoForVfwdauthDBDaoImpl> 目前的数据源是 :VfwdauthDS 
<20151030111035240><11:10:35><CardInfoForVfwdauthDBDaoImpl> 从VfwdauthDS 查询到 【2】 条记录 
<20151030111035240><11:10:35><ResourceSearchFromDBServlet> [20151030111035240]RAS查询返回：{"cardno":"222222","retcode":"0000","retmsg":"success","username":"bbbb"} 
<20151030111035240><11:10:35><ResourceSearchFromDBServlet> end time :20151030111035256 
<20151030111035240><11:10:35><ResourceSearchFromDBServlet> 请求耗时 :0.016秒 

成功了，唯一的logId出现了。

当在linux系统中使用vi编辑器查询某一个交易请求时，查找该logId，该请求可以高亮显示。这样查找方便多了