Java实现日志全链路追踪.精确到一次请求的全部流程

广大程序员在排除线上问题时,会经常遇见各种BUG.处理这些BUG的时候日志就格外的重要.只有完善的日志才能快速有效的定位问题.为了提高BUG处理效率.我决定在日志上面优化.实现每次请求有统一的id.通过id能获取当前接口的全链路流程走向. 

实现效果如下: 一次查询即可找到所有关键信息.不再被多线程日志进行困扰了.

1:日志打印框架log4j ->  logback

logback是springboot默认自带的日志框架。不仅速度更快，而且内存占用也更小. (如果之前没用过log4j的建议先去学习下怎么使用).

打印日志的配置文件如下:  logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<jmxConfigurator/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<Target>System.out</Target>
<encoder>
<charset>UTF-8</charset>
<pattern>%d - [%t] %-5p %c:%L %X - %m%n</pattern>
</encoder>
</appender>
<appender name="DAILY_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<Append>true</Append>
<!--  日志输出路径 -->
<File>/opt/logs/logOut.log</File>
<encoder>
<charset>UTF-8</charset>
<pattern>%d - [%t] %-5p %c:%L %X - %m%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>/opt/logs/logOut.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>7</maxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread][%X{traceId}] %-5level %logger{50} - %msg%n</pattern>
</encoder>
</appender>
<appender name="ROLLING_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>/opt/logs/logOut-error.log</File>
<Append>true</Append>
<encoder>
<charset>UTF-8</charset>
<pattern>%d - [%t] %-5p %c:%L %X - %m%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>ERROR</level>
</filter>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>/opt/logs/logOut-error.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>7</maxHistory>
</rollingPolicy>
</appender><logger name="org.springframework" level="INFO"/>
<root level="INFO">
<appender-ref ref="DAILY_FILE"/>
<appender-ref ref="ROLLING_FILE"/>
</root>
</configuration>

重点是这行代码

<!--格式化输出：%d表示日期，%thread表示线程名，%-5level：级别从左显示5个字符宽度%msg：日志消息，%n是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread][%X{traceId}] %-5level %logger{50} - %msg%n</pattern>

此时的配置文件打印只能出现 年月日-线程名这些关键信息.无法获得每次请求的唯一id.所以我们需要创建一个拦截器.将每次请求生成一个id.通过id把本次请求覆盖到每个流程中.

2.1: 编写 http请求 拦截器

public class TraceWebInterceptor extends HandlerInterceptorAdapter {private static final Logger LOGGER = LoggerFactory.getLogger(TraceWebInterceptor.class);@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {request.setAttribute("startTime", System.currentTimeMillis());//traceOrigin、traceCaller、traceIdString traceOrigin = request.getHeader(TraceConstants.LOG_TRACE_ORIGIN);String traceCaller = request.getHeader(TraceConstants.LOG_TRACE_CALLER);String traceId = request.getHeader(TraceConstants.LOG_TRACE_ID);//如果不存在traceId需要生成if (StringUtils.isBlank(traceId)) {boolean generate = TraceUtil.loadTraceInfo();if(generate) {LOGGER.debug("[生成追踪信息]" + TraceUtil.getTraceInfoString());}}else {//设置MDCMDC.put(TraceConstants.LOG_TRACE_ORIGIN, traceOrigin);MDC.put(TraceConstants.LOG_TRACE_CALLER, traceCaller);MDC.put(TraceConstants.LOG_TRACE_ID, traceId);}//IPString traceIp = IpUtil.getIp(request);MDC.put(TraceConstants.LOG_TRACE_IP, traceIp);//响应返回response.setHeader(TraceConstants.LOG_TRACE_ID, TraceUtil.getTraceId());return super.preHandle(request, response, handler);}@Overridepublic void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws IOException {if (LOGGER.isInfoEnabled()) {long upmsStartTime = (long) request.getAttribute("startTime");long upmsEndTime = System.currentTimeMillis();long upmsIntervalTime = upmsEndTime - upmsStartTime;LOGGER.info("{} {}接口耗时{}毫秒", request.getRequestURL(), request.getMethod(), upmsIntervalTime);}MDC.clear();}

2.2 编写Config类, 将拦截器TraceWebInterceptor添加到容器

@Configuration
@ConditionalOnClass({HandlerInterceptorAdapter.class, MDC.class, HttpServletRequest.class})
public class TraceWebAutoConfiguration implements WebMvcConfigurer {private static List<String> EXCLUDE_PATHS = new ArrayList<>();@Value("${" + TraceConstants.CONFIG_TRACE_EXCLUDE_PATHS + ":}")private String excludePaths;@Beanpublic TraceWebInterceptor traceWebInterceptor() {return new TraceWebInterceptor();}@Overridepublic void addInterceptors(InterceptorRegistry registry) {EXCLUDE_PATHS.add("/error");EXCLUDE_PATHS.add("/actuator/**");if (StringUtils.isNotBlank(excludePaths)) {if (excludePaths.contains(",")) {String[] split = excludePaths.split(",");EXCLUDE_PATHS.addAll(Arrays.asList(split));} else {EXCLUDE_PATHS.add(excludePaths);}}//该方式不能过全部过滤掉registry.addInterceptor(traceWebInterceptor()).order(-100).excludePathPatterns(EXCLUDE_PATHS);}
}

2.3 编写工具类

import javax.servlet.http.HttpServletRequest;public class IpUtil {private static final String UNKNOWN = "unknown";public static String getIp(HttpServletRequest request) {if (request == null) {return UNKNOWN;}String 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("X-Forwarded-For");}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.getHeader("X-Real-IP");}if (ip == null || ip.length() == 0 || UNKNOWN.equalsIgnoreCase(ip)) {ip = request.getRemoteAddr();}return "0:0:0:0:0:0:0:1".equals(ip) ? "127.0.0.1" : ip;}
}

public class TraceConstants {public static final String LOG_TRACE_ORIGIN = "traceOrigin";public static final String LOG_TRACE_CALLER = "traceCaller";public static final String LOG_TRACE_IP = "traceIp";public static final String LOG_TRACE_ID = "traceId";public static final String CONFIG_TRACE_EXCLUDE_PATHS = "trace.exclude.paths";public TraceConstants() {}
}

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;import java.util.UUID;public class TraceUtil {private static boolean simbaHttpClientInterceptorFlag = true;private static boolean sdkInterceptorFlag = false;private static String applicationName;public TraceUtil() {}public static void setApplicationName(String applicationName) {TraceUtil.applicationName = applicationName;}public static String getApplicationName() {return applicationName;}public static boolean getSimbaHttpClientInterceptorFlag() {return simbaHttpClientInterceptorFlag;}public static void setSimbaHttpClientInterceptorFlag(boolean simbaHttpClientInterceptorFlag) {TraceUtil.simbaHttpClientInterceptorFlag = simbaHttpClientInterceptorFlag;}public static boolean getSdkInterceptorFlag() {return sdkInterceptorFlag;}public static void setSdkInterceptorFlag(boolean sdkInterceptorFlag) {TraceUtil.sdkInterceptorFlag = sdkInterceptorFlag;}public static void setTraceCaller(String traceCaller) {MDC.put("traceCaller", traceCaller);}public static String getTraceCaller() {return MDC.get("traceCaller");}public static void setTraceOrigin(String traceOrigin) {MDC.put("traceOrigin", traceOrigin);}public static String getTraceOrigin() {return MDC.get("traceOrigin");}public static void setTraceId(String traceId) {MDC.put("traceId", traceId);}public static void removeTraceId() {MDC.remove("traceId");}public static void clearMdc() {MDC.clear();}public static String getTraceId() {return MDC.get("traceId");}public static String genTraceId() {return UUID.randomUUID().toString().replace("-", "");}public static String getTraceIp() {return MDC.get("traceIp");}public static void setTraceIp(String traceIp) {MDC.put("traceIp", traceIp);}public static boolean loadTraceInfo() {boolean generate = false;String traceId = getTraceId();if (StringUtils.isBlank(traceId)) {traceId = genTraceId();generate = true;}setTraceId(traceId);return generate;}public static String getTraceInfoString() {return "TraceId:" + getTraceId() + ". traceCaller:" + getTraceCaller() + ". traceOrigin:" + getTraceOrigin();}
}

import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.boot.autoconfigure.condition.ConditionalOnClass;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;import javax.servlet.http.HttpServletRequest;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;@Configuration
@ConditionalOnClass({HandlerInterceptorAdapter.class, MDC.class, HttpServletRequest.class})
public class TraceWebAutoConfiguration implements WebMvcConfigurer {private static List<String> EXCLUDE_PATHS = new ArrayList<>();@Value("${" + TraceConstants.CONFIG_TRACE_EXCLUDE_PATHS + ":}")private String excludePaths;@Beanpublic TraceWebInterceptor traceWebInterceptor() {return new TraceWebInterceptor();}@Overridepublic void addInterceptors(InterceptorRegistry registry) {EXCLUDE_PATHS.add("/error");EXCLUDE_PATHS.add("/actuator/**");if (StringUtils.isNotBlank(excludePaths)) {if (excludePaths.contains(",")) {String[] split = excludePaths.split(",");EXCLUDE_PATHS.addAll(Arrays.asList(split));} else {EXCLUDE_PATHS.add(excludePaths);}}//该方式不能过全部过滤掉registry.addInterceptor(traceWebInterceptor()).order(-100).excludePathPatterns(EXCLUDE_PATHS);}
}

import org.apache.commons.lang3.StringUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;public class TraceWebInterceptor extends HandlerInterceptorAdapter {private static final Logger LOGGER = LoggerFactory.getLogger(TraceWebInterceptor.class);@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {request.setAttribute("startTime", System.currentTimeMillis());//traceOrigin、traceCaller、traceIdString traceOrigin = request.getHeader(TraceConstants.LOG_TRACE_ORIGIN);String traceCaller = request.getHeader(TraceConstants.LOG_TRACE_CALLER);String traceId = request.getHeader(TraceConstants.LOG_TRACE_ID);//如果不存在traceId需要生成if (StringUtils.isBlank(traceId)) {boolean generate = TraceUtil.loadTraceInfo();if (generate) {LOGGER.debug("[生成追踪信息]" + TraceUtil.getTraceInfoString());}} else {//设置MDCMDC.put(TraceConstants.LOG_TRACE_ORIGIN, traceOrigin);MDC.put(TraceConstants.LOG_TRACE_CALLER, traceCaller);MDC.put(TraceConstants.LOG_TRACE_ID, traceId);}//IPString traceIp = IpUtil.getIp(request);MDC.put(TraceConstants.LOG_TRACE_IP, traceIp);//响应返回response.setHeader(TraceConstants.LOG_TRACE_ID, TraceUtil.getTraceId());return super.preHandle(request, response, handler);}@Overridepublic void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws IOException {if (LOGGER.isInfoEnabled()) {long upmsStartTime = (long) request.getAttribute("startTime");long upmsEndTime = System.currentTimeMillis();long upmsIntervalTime = upmsEndTime - upmsStartTime;LOGGER.info("{} {}接口耗时{}毫秒", request.getRequestURL(), request.getMethod(), upmsIntervalTime);}MDC.clear();}
}

import org.slf4j.MDC;import java.util.Map;
import java.util.concurrent.*;public class WrapUtil {public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {return () -> {if (context == null) {MDC.clear();} else {MDC.setContextMap(context);}TraceUtil.loadTraceInfo();try {return callable.call();} finally {MDC.clear();}};}public static <T> Callable<T> wrap(final Callable<T> callable) {return wrap(callable, MDC.getCopyOfContextMap());}public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {return () -> {if (context == null) {MDC.clear();} else {MDC.setContextMap(context);}TraceUtil.loadTraceInfo();try {runnable.run();} finally {MDC.clear();}};}public static Runnable wrap(final Runnable runnable) {return wrap(runnable, MDC.getCopyOfContextMap());}public static ThreadPoolExecutor newThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,RejectedExecutionHandler handler) {return new ThreadPoolExecutorMdcWrapper(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);}public static ThreadPoolExecutor newThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {return new ThreadPoolExecutorMdcWrapper(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);}public static ThreadPoolExecutor newThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue) {return new ThreadPoolExecutorMdcWrapper(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);}public static ThreadPoolExecutor newThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue,RejectedExecutionHandler handler) {return new ThreadPoolExecutorMdcWrapper(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);}public static ForkJoinPool newForkJoinPool() {return new ForkJoinPoolMdcWrapper();}public static class ThreadPoolExecutorMdcWrapper extends ThreadPoolExecutor {public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue) {super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);}public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);}public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);}public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,RejectedExecutionHandler handler) {super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);}@Overridepublic void execute(Runnable task) {super.execute(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic <T> Future<T> submit(Runnable task, T result) {return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()), result);}@Overridepublic <T> Future<T> submit(Callable<T> task) {return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic Future<?> submit(Runnable task) {return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));}}public static class ForkJoinPoolMdcWrapper extends ForkJoinPool {public ForkJoinPoolMdcWrapper() {super();}public ForkJoinPoolMdcWrapper(int parallelism) {super(parallelism);}public ForkJoinPoolMdcWrapper(int parallelism, ForkJoinWorkerThreadFactory factory,Thread.UncaughtExceptionHandler handler, boolean asyncMode) {super(parallelism, factory, handler, asyncMode);}@Overridepublic void execute(Runnable task) {super.execute(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic <T> ForkJoinTask<T> submit(Runnable task, T result) {return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()), result);}@Overridepublic <T> ForkJoinTask<T> submit(Callable<T> task) {return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));}}
}

把工具类加上后.此时运行项目. 如果报错就处理下依赖导包. 不报错就说明可以正常使用了. 然后发布代码.运行方法.去查看日志吧. 此时每次请求都已经生成唯一ID了.