`
QING____
  • 浏览: 2228372 次
  • 性别: Icon_minigender_1
  • 来自: 北京
社区版块
存档分类
最新评论

logback日志与MDC机制

    博客分类:
  • JAVA
 
阅读更多

    logback是个比较好用的java日志输出工具包,可配置型高,而且性能优秀。

 

一、Layout描述

1、%logger{length}、%c{length}、%lo{length}:在日志事件的源点输出logger的名称,比如

    1)LoggerFactory.getLogger(TestMain.class),此时%logger的值为“com.xxx.TestMain”

    2)LoggerFactory.getLogger("FILE-LOGGER"),此时其值为“FILE-LOGGER”。

    其中{length}为可选项,length值为数字类型(>=0),在不丢失含义的情况下来限定logger名字的长度(缩短);在指定length情况下,将会直接返回“.”字符最右端的子字符串。如下为示例:

配置                      logger名                            结果
%logger	        mainPackage.sub.sample.Bar	mainPackage.sub.sample.Bar
%logger{0}	mainPackage.sub.sample.Bar	Bar
%logger{5}	mainPackage.sub.sample.Bar	m.s.s.Bar
%logger{10}	mainPackage.sub.sample.Bar	m.s.s.Bar
%logger{15}	mainPackage.sub.sample.Bar	m.s.sample.Bar
%logger{16}	mainPackage.sub.sample.Bar	m.sub.sample.Bar
%logger{26}	mainPackage.sub.sample.Bar	mainPackage.sub.sample.Bar 

    由此可见,无论length如何设置,“Bar” 总会完整输出;当length过小时,将会根据“.”分割且只输出缩写;根据length的情况,从最右端开始逐级补全。为了易读,我们尽可能使用%logger输出全名。

 

2、%C{length}、%class{length}:输出发生日志事件的调用类的全限定名。与%logger类似,{length}可选项来限定类名的长度,适度进行缩写。

3、%d{pattern}、%date{pattern}、%d{pattern,timezone}、%date{pattern,timezone}:输出日志事件的时间;{pattern}为可选项,用于声明时间的格式,比如%d{yyyy-MM-dd HH:mm:ss},pattern必须为“java.text.SimpleDateFormat”类可兼容的格式。

4、%F、%file:输出发生日志请求的java源文件名,产生文件名信息不是特别的快,有一定的性能损耗,除非对执行速度不敏感否则应该避免使用此选项。(比如输出:TestMain.java,默认异常栈中会输出类名)

5、%caller{depth}、%caller{depthStart..depthEnd}:输出产生日志事件的调用者位置信息,{depth}为可选项;位置信息依赖于JVM实现,不过通常会包含调用方法的全限定名、文件名和行号。

假如:TestMain.java中main()-->test1()-->test2(),在test2方法中触发日志事件,假如%caller{3}将会输出:

Caller+0	at com.test.demo.TestMain2.test2(TestMain2.java:26)
Caller+1	at com.test.demo.TestMain2.test1(TestMain2.java:18)
Caller+2	at com.test.demo.TestMain2.main(TestMain2.java:14)

    这个配置项,对我们排查问题非常有用。不过在exception时,异常栈中已经包含了全部的追踪栈。

 

6、%L、%line:输出发生日志请求的源文件行号,产生行号信息不是非常的快速,有一定的性能损耗,除非对执行速度不敏感否则应该避免使用此选项。(默认异常栈中会输出行号)

7、%m、%msg、%message:在日志中输出应用提供的message。

    比如:LOGGER.error("message",exception),输出“message”和exception栈。

8、%M、%method:输出发出日志记录请求的方法名称,产生方法名不是特别快速。

9、%n:输出一个行分隔符,即换行符。(取决于运行平台,可能是“\n”,"\r\n")

10、%p、%le、%level:输出日志事件的level。

11、%t、%thread:输出产生日志事件的线程名称。

12、%ex{depth}、%exception{depth}:输出日志事件相关的异常栈,默认会输出异常的全跟踪栈。(%m会包含此部分)

13、%nopex:输出日志数据,但是忽略exception。

 

二、pom.xml

<dependency>
      <groupId>ch.qos.logback</groupId>
      <artifactId>logback-classic</artifactId>
      <version>1.1.8</version>
</dependency>
<dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-api</artifactId>
      <version>1.7.22</version>
</dependency>

  

三、logback.xml样例(放置在classpath下即可)

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOG_HOME" value="logs"/>
    <property name="encoding" value="UTF-8"/>
    <appender name="DEFAULT" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_HOME}/test.log</file>
        <Append>true</Append>
        <prudent>false</prudent>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{50} %line - %m%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!--归档日志文件名-->
            <FileNamePattern>${LOG_HOME}/test.log.%d{yyyy-MM-dd}</FileNamePattern>
            <maxHistory>15</maxHistory> <!-- 最多保存15天历史文件 -->
        </rollingPolicy>
    </appender>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{50} %line - %m%n</pattern>
        </encoder>
    </appender>

    <logger name="com.test.demo" level="DEBUG">
        <appender-ref ref="DEFAULT"/>
    </logger>
    <!-- 日志输出级别 -->
    <root level="DEBUG">
        <appender-ref ref="DEFAULT"/>
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

 

四、MDC

    logback内置的日志字段还是比较少,如果我们需要打印有关业务的更多的内容,包括自定义的一些数据,需要借助logback MDC机制,MDC为“Mapped Diagnostic Context”(映射诊断上下文),即将一些运行时的上下文数据通过logback打印出来;此时我们需要借助org.sl4j.MDC类。

    MDC类基本原理其实非常简单,其内部持有一个InheritableThreadLocal实例,用于保存context数据,MDC提供了put/get/clear等几个核心接口,用于操作ThreadLocal中的数据;ThreadLocal中的K-V,可以在logback.xml中声明,最终将会打印在日志中。

MDC.put("userId",1000);

    那么在logback.xml中,即可在layout中通过声明“%X{userId}”来打印此信息。

    在使用MDC时需要注意一些问题,这些问题通常也是ThreadLocal引起的,比如我们需要在线程退出之前清除(clear)MDC中的数据;在线程池中使用MDC时,那么需要在子线程退出之前清除数据;可以调用MDC.clear()方法。

 

    在JAVA WEB项目中,为了更好的跟踪请求,我们可能希望在日志中打印比如HTTP header信息、运行时的一些token、code等,那么我们借助MDC即可非常便捷的实现。我们开发一个Filter,此Filter用于解析Http请求中的一些参数,并将这些参数添加到MDC中,并在logback.xml中声明我们关注的字段。

 

    HttpRequestMDCFilter.java

import org.slf4j.MDC;

import javax.servlet.*;
import javax.servlet.http.Cookie;
import javax.servlet.http.HttpServletRequest;
import java.io.IOException;
import java.net.InetAddress;
import java.net.NetworkInterface;
import java.util.Enumeration;

/**
 * Created by liuguanqing on 16/12/28.
 * 在logback日志输出中增加MDC参数选项
 * 注意,此Filter尽可能的放在其他Filter之前
 *
 * 默认情况下,将会把“requestId”、“requestSeq”、“localIp”、“timestamp”、“uri”添加到MDC上下文中。
 * 1)其中requestId,requestSeq为调用链跟踪使用,开发者不需要手动修改他们。
 * 2)localIp为当前web容器的宿主机器的本地IP,为内网IP。
 * 3)timestamp为请求开始被servlet处理的时间戳,设计上为被此Filter执行的开始时间,可以使用此值来判断内部程序执行的效率。
 * 4)uri为当前request的uri参数值。
 *
 * 我们可以在logback.xml文件的layout部分,通过%X{key}的方式使用MDC中的变量
 */
public class HttpRequestMDCFilter implements Filter {

    /**
     *  是否开启cookies映射,如果开启,那么将可以在logback中使用
     *  %X{_C_:<name>}来打印此cookie,比如:%X{_C_:user};
     *  如果开启此选项,还可以使用如下格式打印所有cookies列表:
     *  格式为:key:value,key:value
     *  %X{requestCookies}
     */

    private boolean mappedCookies;
    /**
     * 是否开启headers映射,如果开启,将可以在logback中使用
     * %X{_H_:<header>}来打印此header,比如:%X{_H_:X-Forwarded-For}
     * 如果开启此参数,还可以使用如下格式打印所有的headers列表:
     * 格式为:key:value,key:value
     * %X{requestHeaders}
     */
    private boolean mappedHeaders;

    /**
     * 是否开启parameters映射,此parameters可以为Get的查询字符串,可以为post的Form Entries
     * %X{_P_:<parameter>}来答应此参数值,比如:%X{_P_:page}
     * 如果开启此参数,还可以使用如下格式打印所有的headers列表:
     * 格式为:key:value,key:value
     * %X{requestParameters}
     */
    private boolean mappedParameters;

    private String localIp;//本机IP


    //all headers,content as key:value,key:value
    private static final String HEADERS_CONTENT = "requestHeaders";

    //all cookies
    private static final String COOKIES_CONTENT = "requestCookies";

    //all parameters
    private static final String PARAMETERS_CONTENT = "requestParameters";

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        mappedCookies = Boolean.valueOf(filterConfig.getInitParameter("mappedCookies"));
        mappedHeaders = Boolean.valueOf(filterConfig.getInitParameter("mappedHeaders"));
        mappedParameters = Boolean.valueOf(filterConfig.getInitParameter("mappedParameters"));
        //getLocalIp
        localIp = getLocalIp();
    }

    private String getLocalIp() {
        try {
            //一个主机有多个网络接口
            Enumeration<NetworkInterface> netInterfaces = NetworkInterface.getNetworkInterfaces();
            while (netInterfaces.hasMoreElements()) {
                NetworkInterface netInterface = netInterfaces.nextElement();
                //每个网络接口,都会有多个"网络地址",比如一定会有loopback地址,会有siteLocal地址等.以及IPV4或者IPV6    .
                Enumeration<InetAddress> addresses = netInterface.getInetAddresses();
                while (addresses.hasMoreElements()) {
                    InetAddress address = addresses.nextElement();
                    //get only :172.*,192.*,10.*
                    if (address.isSiteLocalAddress() && !address.isLoopbackAddress()) {
                        return address.getHostAddress();
                    }
                }
            }
        }catch (Exception e) {
            //
        }
        return null;
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest hsr = (HttpServletRequest)request;
        try {
            mdc(hsr);
        } catch (Exception e) {
            //
        }

        try {
            chain.doFilter(request,response);
        } finally {
            MDC.clear();//must be,threadLocal
        }

    }

    private void mdc(HttpServletRequest hsr) {
        MDC.put(MDCConstants.LOCAL_IP_MDC_KEY,localIp);
        MDC.put(MDCConstants.REQUEST_ID_MDC_KEY,hsr.getHeader(MDCConstants.REQUEST_ID_HEADER));
        String requestSeq = hsr.getHeader(MDCConstants.REQUEST_SEQ_HEADER);
        if(requestSeq != null) {
            String nextSeq = requestSeq + "0";//seq will be like:000,real seq is the number of "0"
            MDC.put(MDCConstants.NEXT_REQUEST_SEQ_MDC_KEY,nextSeq);
        }else {
            MDC.put(MDCConstants.NEXT_REQUEST_SEQ_MDC_KEY,"0");
        }
        MDC.put(MDCConstants.REQUEST_SEQ_MDC_KEY,requestSeq);
        MDC.put(MDCConstants.TIMESTAMP,"" + System.currentTimeMillis());
        MDC.put(MDCConstants.URI_MDC_KEY,hsr.getRequestURI());

        if(mappedHeaders) {
            Enumeration<String> e = hsr.getHeaderNames();
            if(e != null) {
                //
                while (e.hasMoreElements()) {
                    String header = e.nextElement();
                    String value = hsr.getHeader(header);
                    MDC.put(MDCConstants.HEADER_KEY_PREFIX + header, value);
                    //
                }
               
            }
        }

        if(mappedCookies) {
            Cookie[] cookies = hsr.getCookies();
            if(cookies != null && cookies.length > 0) {
                //
                for(Cookie  cookie : cookies) {
                    String name = cookie.getName();
                    String value = cookie.getValue();
                    MDC.put(MDCConstants.COOKIE_KEY_PREFIX + name,value);
                    //
                }
               
            }
        }

        if(mappedParameters) {
            Enumeration<String> e = hsr.getParameterNames();
            if(e != null) {
                //
                while (e.hasMoreElements()) {
                    String key = e.nextElement();
                    String value = hsr.getParameter(key);
                    MDC.put(MDCConstants.PARAMETER_KEY_PREFIX + key,value);
                    //
                }
                
            }
        }
    }

    @Override
    public void destroy() {

    }
}

 

    备注:request_seq的值没有设计为数字类型,而是使用“0”的个数表示seq的实际值,比如“0”表示seq=1,“00”表示seq=2,依此论推;之所以这么设计的原因是:对于nginx、tomcat等等,在它们的日志中对seq进行数字自增操作是比较麻烦的,但是在字符串后面追加值是很容易实现的,因此,我们使用“0”的个数表示seq的实际值。

    在设计request_seq时,我还遇到了一个有关“艺术”的问题,这个seq的值在何时进行“自增”?是请求每经过一层就自增?还是一个实际的请求结束后才自增?比如一个http请求,经过nginx、tomcat到达app1 servlet,然后再由此servlet转发给app2,那么seq的变化过程是:

     1)app1.nginx=1,app1.tomcat=2,app.servlet=3,app2.nginx=4,app2.tomcat=5.....(按照请求经过的处理层,每个层接收到请求后对seq自增)

     2)app1.nginx=1,app1.tomcat=1,app1.servlet=1,app2.nginx=2,app2.tomcat=2....(按照请求的生命周期,只有请求在转发给其他外部应用之前对seq自增,比如app1.servlet在转发给app2之前,先自增seq,然后再转发请求)

    后来,经过讨论和认真考虑,为了实用、便于统计分析等多方面因素,我们决定采用2)方式。

 

    如下为几个辅助类:

    MDCConstants.java

public class MDCConstants {

    public static final String REQUEST_ID_HEADER = "X-Request-ID";

    public static final String REQUEST_SEQ_HEADER = "X-Request-Seq";

    public static final String REQUEST_ID_MDC_KEY = "requestId";

    public static final String REQUEST_SEQ_MDC_KEY = "requestSeq";

    //追踪链下发时,使用的seq,由Filter生成,通常开发者不需要修改它。
    public static final String NEXT_REQUEST_SEQ_MDC_KEY = "nextRequestSeq";

    public static final String LOCAL_IP_MDC_KEY = "localIp";

    public static final String URI_MDC_KEY = "uri";

    public static final String TIMESTAMP = "_timestamp_";//进入filter的时间戳

    public static final String COOKIE_KEY_PREFIX = "_C_";

    public static final String HEADER_KEY_PREFIX = "_H_";

    public static final String PARAMETER_KEY_PREFIX = "_P_";
}

 

    MDCUtils.java

public class MDCUtils {

    public static String get(String key) {
        return MDC.get(key);
    }

    /**
     * 如果MDC中不包含key,则返回defaultValue
     * @param key
     * @param defaultValue
     * @return
     */
    public static String get(String key,String defaultValue) {
        String value = MDC.get(key);
        return value == null ? defaultValue : value;
    }

    public static String getRequestId() {
        return MDC.get(MDCConstants.REQUEST_ID_MDC_KEY);
    }

    public static String getRequestSeq() {
        return MDC.get(MDCConstants.REQUEST_SEQ_MDC_KEY);
    }

    public static String getUri() {
        return MDC.get(MDCConstants.URI_MDC_KEY);
    }

    /**
     * 获取此请求进入MDCFilter的时间戳
     * @return
     */
    public static String getTimestampOfFilter() {
        return MDC.get(MDCConstants.TIMESTAMP);
    }

    /**
     * 获取当前server的本地IP
     * @return
     */
    public static String getLocalIp() {
        return MDC.get(MDCConstants.LOCAL_IP_MDC_KEY);
    }

    public static String nextRequestSeq() {
        return MDC.get(MDCConstants.NEXT_REQUEST_SEQ_MDC_KEY);
    }

    public static String getHeader(String header) {
        return MDC.get(MDCConstants.HEADER_KEY_PREFIX + header);
    }

    public static String getCookie(String name) {
        return MDC.get(MDCConstants.COOKIE_KEY_PREFIX + name);
    }

    public static String getParameter(String name) {
        return MDC.get(MDCConstants.PARAMETER_KEY_PREFIX + name);
    }

    //如果你手动设置了MDC的值,请你要么配置HttpRequestMDCFilter,要么就是自己在合适的地方执行clear()方法
    public static void put(String key,String value) {
        MDC.put(key,value);
    }

    public static void clear() {
        MDC.clear();
    }

    public static void remove(String key) {
        MDC.remove(key);
    }
}

 

    此后我们需要在web.xml中配置此Filter,建议将此Filter最为最顶层(可以放在CharactorEncodingFilter之后,避免乱码)。此Filter可以解析cookie、headers等,那么此后我们将可以在logback.xml中使用它们。

分享到:
评论

相关推荐

Global site tag (gtag.js) - Google Analytics