slf4j日志添加全局唯一的请求ID（requestId，MDC）

最新推荐文章于 2024-09-21 21:25:06 发布

石头wang

最新推荐文章于 2024-09-21 21:25:06 发布

阅读量1w

点赞数 9

分类专栏： Java高级文章标签：日志 slf4j MDC requestid

本文链接：https://blog.csdn.net/w8y56f/article/details/103496534

版权

Java高级专栏收录该内容

37 篇文章 7 订阅

订阅专栏

背景

我们希望springboot默认的日志框架slf4j，在打印日志时，每行数据都有一个请求ID，这样就很方面追踪日志。并且可以在linux中用将所有该请求ID的日志写在单独的文件里（grep 你的RequestId xxx.log > 该请求ID的所有日志.log）

(其实是有一些链路追踪的框架的，比如zipkin等，本文写这个是一个不想用这些框架的情况下的方案）

办法

slf4j有个MDC的类，是ThreadLocal的实现，保存在这里的变量会绑定到某个请求线程，于是在该请求的线程里的日志代码都可以使用设入的变量。例如：

MDC中设入了名为 RequestId 变量，则日志格式可以配置

%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{RequestId}] [%thread] %-5level %logger{36} - %msg%n

其中 %X{参数名}  是引用的语法

详细的步骤

我们必须在springboot项目里定义一个拦截器，可以是javax.servlet.Filter，也可以是spring的AOP，反正就是要拦截所有请求并在MDC中设入变量。

设入MDC的变量最好在finally中进行clear，以避免不必要的麻烦。注意要用clear()方法，不要一个个key去remove，避免以后添加了新的变量后忘记remove

代码如下：

package com.wyf.test.requestidlog.mdc;

import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.UUID;

/**
 * 在日志上下文增加参数，在日志中可以打印该参数，如RequestId，则日志配置：%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{RequestId}] [%thread] %-5level %logger{36} - %msg%n
 * 则 RequestId 会打印在中括号里，%X{参数名}  是格式
 *
 * 该bean自动被注册，默认的mapping是/*，参考文档
 * https://docs.spring.io/spring-boot/docs/2.2.1.RELEASE/reference/htmlsingle/#howto-add-a-servlet-filter-or-listener-as-spring-bean （说明了只要是Filter/Servlet/*Listener的bean自动配置）
 * https://docs.spring.io/spring-boot/docs/2.2.1.RELEASE/reference/htmlsingle/#boot-features-embedded-container-servlets-filters-listeners-beans （说明了Filters默认map to /*）
 *
 * 如果需要复杂点的配置，例如多个Filter的顺序、mapping路径的指定，可以在@Configuration类里使用@Bean来产生所需的bean，产生的过程即可指定顺序和mapping路径
 *
 * @author Stone
 * @version V1.0.0
 * @date 2019/12/10
 */
@Component
public class MDCFilter implements Filter {
    /**
     * 设置响应头，响应头名字（惯例是大写）
     */
    private static final String REQUEST_ID_HEADER = "RequestId";
    /**
     * 设置到 MDC 里的key（惯例使用小驼峰，为了统一这里也用大写）
     */
    private static final String REQUEST_ID = "RequestId";

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        HttpServletResponse httpResponse = (HttpServletResponse) response;

        String requestId = httpRequest.getHeader(REQUEST_ID_HEADER);
        if (requestId == null) {
            requestId = UUID.randomUUID().toString();
        }

        // 还有更加准确的方法
        String ip = getRequestSourceIp(httpRequest);

        MDC.put(REQUEST_ID, requestId);
        MDC.put("IP", ip);
        httpResponse.setHeader(REQUEST_ID_HEADER, requestId);

        try {
            chain.doFilter(request, response);
        } finally {
            MDC.clear();
        }
    }

    @Override
    public void destroy() {
    }


    /**
     * 获取请求来源的IP,可以适应前置部署有Nginx等反向代理软件等的情况. HTTP_CLIENT_IP 无法伪造，所以放在第一个
     * http://blog.csdn.net/songylwq/article/details/7701718
     *
     * @param request
     * @return
     * @author Stone
     */
    public static String getRequestSourceIp(HttpServletRequest request) {
        String ip = request.getHeader("HTTP_CLIENT_IP");

        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("HTTP_X_FORWARDED_FOR");
        }

        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("HTTP_X_FORWARDED");
        }

        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("HTTP_FORWARDED");
        }

        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("X-FORWARDED-FOR");
        }
        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("Proxy-Client-IP");
        }
        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getHeader("WL-Proxy-Client-IP");
        }

        if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip)) {
            ip = request.getRemoteAddr();
        }
        return ip;
    }
}

lockback-spring.xml配置如下：

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <target>System.out</target>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{RequestId}] [%X{IP}] [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

上述代码配置了@Component，会被spring容器管理，其是javax.servlet.Filter的实现，所以默认拦截器能生效，拦截所有/* 的请求。

运行效果

2019-12-11 17:18:22.451 [fd4053e3-2a79-4277-a16b-2390f5b62ce3] [0:0:0:0:0:0:0:1] [http-nio-8080-exec-1] INFO  c.w.t.r.controller.TestController - === log ===

补充

思考：

对于junit或main方法里打印的日志，能获取到RequestId的变量吗?
获取不到，因为不是http(s)请求，所以不会进入拦截器，故未往MDC中设入值
父线程能打印日志，其子线程能获取到吗?
打印不来，因为MDC是ThreadLocal的实现，父线程绑定了变量但是子线程没有。

这时候必须由父线程传入，下面演示的代码使用了 “装饰者模式” 的设计模式，重新写了Runnable和Callable，使用这个替代Runnable和Callable就能让子线程获取到父线程里的变量

MyRunnable

package com.wyf.test.requestidlog.mdc;

import org.slf4j.MDC;

import java.util.HashMap;
import java.util.Map;

/**
 * 封装Runnable接口，装饰者模式
 *
 * @author Stone
 * @version V1.0.0
 * @date 2019/12/10
 */
public class MyRunnable implements Runnable {
    private Runnable runnable;
    private Map<String, String> map;

    /**
     * 传入runnable类，并获取主线程中的所有参数（调用该构造器是父线程，所以这里的MDC.getXxxx获取到绑定在父线程的变量）
     * @param runnable
     */
    public MyRunnable(Runnable runnable) {
        this.runnable = runnable;
        this.map = MDC.getCopyOfContextMap();
    }

    @Override
    public void run() {
        // 可能是null，必须判断，追踪进代码可见null时会发生NPE
        if (map != null) {
            MDC.setContextMap(map);
        }
        try {
            runnable.run();
        } finally {
            // 即使未执行setContextMap，这里可以clear不出错
            MDC.clear();
        }
    }
}

MyCallable

package com.wyf.test.requestidlog.mdc;

import org.slf4j.MDC;

import java.util.Map;
import java.util.concurrent.Callable;

/**
 * 封装MyCallable接口，装饰者模式
 *
 * @author Stone
 * @version V1.0.0
 * @date 2019/12/10
 */
public class MyCallable<V> implements Callable<V> {
    private Callable<V> callable;
    private Map<String, String> map;

    public MyCallable(Callable<V> callable) {
        this.callable = callable;
        this.map = MDC.getCopyOfContextMap();
    }

    @Override
    public V call() throws Exception {
        // 可能是null，必须判断，追踪进代码可见null时会发生NPE
        if (map != null) {
            MDC.setContextMap(map);
        }
        try {
            return callable.call();
        } finally {
            // 即使未执行setContextMap，这里可以clear不出错
            MDC.clear();
        }
    }
}

使用 MyRunnable 和 MyCallable
3.1 TestController

package com.wyf.test.requestidlog.controller;

import com.wyf.test.requestidlog.mdc.MyRunnable;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.Date;

/**
 * @author Stone
 * @version V1.0.0
 * @date 2019/12/10
 */
@RestController
@Slf4j
public class TestController {

    /**
     * 能打印出RequestId
     *
     * @return
     */
    @GetMapping("/log")
    public String log() {
        log.info("=== log ===");
        return "log," + new Date();
    }

    /**
     * 主线程能打印RequestId，子线程不能
     *
     * @return
     */
    @GetMapping("/log/sub")
    public String logSubThread() {
        log.info("=== main thread ===");

        new Thread(new Runnable() {
            @Override
            public void run() {
                log.info("=== sub thread ===");
            }
        }).start();

        return "log," + new Date();
    }

    /**
     * 父线程、子线程都能打印出来
     *
     * @return
     */
    @GetMapping("/log/sub2")
    public String logSubThreadWithRequestId() {
        log.info("=== main thread ===");

        new Thread(new MyRunnable(new Runnable() {
            @Override
            public void run() {
                log.info("=== sub thread ===");
            }
        })).start();

        return "log," + new Date();
    }


    /**
     * 即使多层，只要使用MyRunnable即可
     *
     * @return
     */
    @GetMapping("/log/sub3")
    public String logSubThreadWithRequestId2() {
        log.info("=== main thread ===");

        new Thread(new MyRunnable(new Runnable() {
            @Override
            public void run() {
                log.info("=== sub thread ===");

                new Thread(new MyRunnable(new Runnable() {
                    @Override
                    public void run() {
                        log.info("=== sub sub thread ===");
                    }
                })).start();
            }
        })).start();

        return "log," + new Date();
    }

    /**
     * 因为是main方法，并未加载springboot的配置，包括log的配置。所以是按照默认的log的打印格式打印出来的，即并不带上 %X{RequestId} 的配置，
     * 况且本身这个方法非http(s)请求故未在拦截器中设入RequestId
     *
     * @param args
     */
    public static void main(String[] args) {
        log.info("=== 打印不出RequestId ====");
    }


    @GetMapping("/")
    public String hello() {
        return "hello," + new Date();
    }
}

3.2 CallableController

package com.wyf.test.requestidlog.controller;

import com.wyf.test.requestidlog.mdc.MyCallable;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.util.Date;
import java.util.concurrent.*;

/**
 * @author Stone
 * @version V1.0.0
 * @date 2019/12/10
 */
@RestController
@Slf4j
public class CallableController {
    /**
     * 注意不要定义成1，否则 `/log/callable2` 里会死循环（外层使用了唯一的线程，在内存又需要等待这个线程可用）
     */
    private ExecutorService threadPool = Executors.newFixedThreadPool(10);

    @GetMapping("/log/callable")
    public String logCallable() throws ExecutionException, InterruptedException {
        log.info("=== main thread ===");

        Future<String> future = threadPool.submit(new MyCallable<String>(new Callable<String>() {
            @Override
            public String call() throws Exception {
                log.info("=== sub thread ===");
                return "ok_from_sub";
            }
        }));

        log.info("=== main wait for return value:" + future.get());

        return "log," + new Date();
    }

    @GetMapping("/log/callable2")
    public String logCallable2() throws ExecutionException, InterruptedException {
        log.info("=== main thread ===");

        Future<String> future = threadPool.submit(new MyCallable<String>(new Callable<String>() {
            @Override
            public String call() throws Exception {
                log.info("=== sub thread ===");


                Future<String> subsubFuture = threadPool.submit(new MyCallable<String>(new Callable<String>() {
                    @Override
                    public String call() throws Exception {
                        log.info("=== sub sub thread ===");

                        return "ok_from_sub_sub";
                    }
                }));
                String value = subsubFuture.get();

                return value;
            }
        }));

        log.info("=== main wait for return value:" + future.get());


        return "log," + new Date();
    }
}

补充

上述的拦截器见到一个细节：在响应中写了一个Header，即httpResponse.setHeader(REQUEST_ID_HEADER, requestId); 这是一个好的实践，即使不看日志，从浏览器中也可以看到请求的RequestId，方便回到日志中进行搜索
建议使用AOP的方式拦截
这样即使是直接调用controller方法，也能够进行拦截并设置对应的参数到MDC，如果是javax.servlet.Filter 或者其他拦截器，只能拦截http(s)请求