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

野性酷女 2023-06-21 07:22 3阅读 0赞

### 背景 ###

我们希望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就能让子线程获取到父线程里的变量

1.  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();
            }
        }
    }

1.  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();
            }
        }
    }

1.  使用 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)请求