广大程序员在排除线上问题时,会经常遇见各种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);
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
request.setAttribute("startTime", System.currentTimeMillis());
//traceOrigin、traceCaller、traceId
String 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 {
//设置MDC
MDC.put(TraceConstants.LOG_TRACE_ORIGIN, traceOrigin);
MDC.put(TraceConstants.LOG_TRACE_CALLER, traceCaller);
MDC.put(TraceConstants.LOG_TRACE_ID, traceId);
}
//IP
String 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);
}
@Override
public 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;
@Bean
public TraceWebInterceptor traceWebInterceptor() {
return new TraceWebInterceptor();
}
@Override
public 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;
@Bean
public TraceWebInterceptor traceWebInterceptor() {
return new TraceWebInterceptor();
}
@Override
public 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);
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
request.setAttribute("startTime", System.currentTimeMillis());
//traceOrigin、traceCaller、traceId
String 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 {
//设置MDC
MDC.put(TraceConstants.LOG_TRACE_ORIGIN, traceOrigin);
MDC.put(TraceConstants.LOG_TRACE_CALLER, traceCaller);
MDC.put(TraceConstants.LOG_TRACE_ID, traceId);
}
//IP
String 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);
}
@Override
public 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);
}
@Override
public void execute(Runnable task) {
super.execute(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> Future<T> submit(Runnable task, T result) {
return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()), result);
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public 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);
}
@Override
public void execute(Runnable task) {
super.execute(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> ForkJoinTask<T> submit(Runnable task, T result) {
return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()), result);
}
@Override
public <T> ForkJoinTask<T> submit(Callable<T> task) {
return super.submit(WrapUtil.wrap(task, MDC.getCopyOfContextMap()));
}
}
}
把工具类加上后.此时运行项目. 如果报错就处理下依赖导包. 不报错就说明可以正常使用了. 然后发布代码.运行方法.去查看日志吧. 此时每次请求都已经生成唯一ID了.