廣大程序員在排除線上問題時,會經常遇見各種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了.