解決的問題

接口報錯，如何快速定位問題？這個需要日志的輔助，一般錯誤日志中有詳細的堆棧信息，具體是哪行代碼報錯，都可以看到。線程日志交差打印，要想快速定位問題，前提是要能夠快速定位日志。

日志量一般都是很大的，如何能夠從大量日志中找到自己需要的日志呢？

依賴原始的logback配置，很難從某服務龐雜的日志中，單獨找尋出某次線程API調用的全部日志。

解決方案

1、服務端入口處可以生成一個唯一的id，記做：traceId

2、日志中均需要輸出traceId的值

3、接口返回值中，添加一個通用的字段：traceId，將上面的traceId作為這個字段的值

• Controller層返回的統一返回值對象R
• 全局異常處理返回的統一返回值對象R

5、這樣前端發現接口有問題的時候，直接將這個traceId提供給我們，我們便可以在日志中快速查詢出對應的日志。使用 grep 'traceId' xxx.log 語句就能準確的定位到目標日志。

MDC

• 日志追蹤目標是每次請求級別的，也就是說同一個接口的每次請求，都應該有不同的traceId。

• 每次接口請求，都是一個單獨的線程，所以自然我們很容易考慮到通過ThreadLocal實現上述需求。

• 考慮到logback本身已經提供了類似的功能MDC，所以直接使用MDC進行實現。

• 關于MDC的簡述

  • Mapped Diagnostic Context，即：映射診斷環境。
  • MDC是 log4j 和 logback 提供的一種方便在多線程條件下記錄日志的功能。
  • MDC 可以看成是一個與當前線程綁定的哈希表，可以往其中添加鍵值對。

• 關于MDC的關鍵操作

  • 向MDC中設置值：MDC.put(key, value);
  • 從MDC中取值：MDC.get(key);
  • 將MDC中內容打印到日志中：%X{key}

假定已經解決了traceId的存放問題，那么何時進行traceId的存放呢？其實有多重實現思路，例如：過濾器、AOP、攔截器等等。

具體邏輯

yml

server:port: 8081spring:profiles:active: devapplication:name: springboot-logmain:allow-bean-definition-overriding: true

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration  scan="true" scanPeriod="10 seconds"><!-- 日志級別從低到高分為TRACE < DEBUG < INFO < WARN < ERROR < FATAL，如果設置為WARN，則低于WARN的信息都不會輸出 --><!-- scan:當此屬性設置為true時，配置文件如果發生改變，將會被重新加載，默認值為true --><!-- scanPeriod:設置監測配置文件是否有修改的時間間隔，如果沒有給出時間單位，默認單位是毫秒。當scan為true時，此屬性生效。默認的時間間隔為1分鐘。 --><!-- debug:當此屬性設置為true時，將打印出logback內部日志信息，實時查看logback運行狀態。默認值為false。 --><contextName>logback</contextName><!-- name的值是變量的名稱，value的值時變量定義的值。通過定義的值會被插入到logger上下文中。定義變量后，可以使“${}”來使用變量。 --><property name="log.path" value="logs/log" /><!-- 彩色日志 --><!-- 配置格式變量：CONSOLE_LOG_PATTERN 彩色日志格式 --><!-- magenta:洋紅 --><!-- boldMagenta:粗紅--><!-- cyan:青色 --><!-- white:白色 --><!-- magenta:洋紅 --><property name="CONSOLE_LOG_PATTERN"value="%X{traceId}|%yellow(%date{yyyy-MM-dd HH:mm:ss}) |%highlight(%-5level) |%blue(%thread) |%blue(%file:%line) |%green(%logger) |%cyan(%msg%n)"/><!--輸出到控制臺--><appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"><!--此日志appender是為開發使用，只配置最底級別，控制臺輸出的日志級別是大于或等于此級別的日志信息--><!-- 例如：如果此處配置了INFO級別，則后面其他位置即使配置了DEBUG級別的日志，也不會被輸出 --><!--<filter class="ch.qos.logback.classic.filter.ThresholdFilter"><level>INFO</level></filter>--><encoder><Pattern>${CONSOLE_LOG_PATTERN}</Pattern><!-- 設置字符集 --><charset>UTF-8</charset></encoder></appender><!--輸出到文件--><!-- 時間滾動輸出 level為 INFO 日志 --><appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在記錄的日志文件的路徑及文件名 --><file>${log.path}/log_info.log</file><!--日志文件輸出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset></encoder><!-- 日志記錄器的滾動策略，按日期，按大小記錄 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><!-- 每天日志歸檔路徑以及格式 --><fileNamePattern>${log.path}/info/log-info-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天數--><maxHistory>15</maxHistory></rollingPolicy><!-- 此日志文件只記錄info級別的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>INFO</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!-- 時間滾動輸出 level為 WARN 日志 --><appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在記錄的日志文件的路徑及文件名 --><file>${log.path}/log_warn.log</file><!--日志文件輸出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset> <!-- 此處設置字符集 --></encoder><!-- 日志記錄器的滾動策略，按日期，按大小記錄 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><fileNamePattern>${log.path}/warn/log-warn-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天數--><maxHistory>15</maxHistory></rollingPolicy><!-- 此日志文件只記錄warn級別的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>warn</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!-- 時間滾動輸出 level為 ERROR 日志 --><appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在記錄的日志文件的路徑及文件名 --><file>${log.path}/log_error.log</file><!--日志文件輸出格式--><encoder><pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern><charset>UTF-8</charset> <!-- 此處設置字符集 --></encoder><!-- 第一種方式:日志記錄器的滾動策略，按日期，按大小記錄 --><rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"><fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.%i.log</fileNamePattern><timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"><maxFileSize>100MB</maxFileSize></timeBasedFileNamingAndTriggeringPolicy><!--日志文件保留天數--><maxHistory>15</maxHistory></rollingPolicy><!-- 第二種方式:指定日志文件拆分和壓縮規則 --><!-- 指定日志文件拆分和壓縮規則 --><!--        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">--><!--            &lt;!&ndash; 通過指定壓縮文件名稱，來確定分割文件方式&ndash;&gt;--><!--            <fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.log%i.zip</fileNamePattern>--><!--            &lt;!&ndash;  文件拆分大小  &ndash;&gt;--><!--            <maxFileSize>1MB</maxFileSize>--><!--            &lt;!&ndash;日志文件保留天數&ndash;&gt;--><!--            <maxHistory>15</maxHistory>--><!--        </rollingPolicy>--><!-- 此日志文件只記錄ERROR級別的 --><filter class="ch.qos.logback.classic.filter.LevelFilter"><level>ERROR</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter></appender><!--<logger>用來設置某一個包或者具體的某一個類的日志打印級別、以及指定<appender>。<logger>僅有一個name屬性，一個可選的level和一個可選的addtivity屬性。name:用來指定受此logger約束的某一個包或者具體的某一個類。level:用來設置打印級別，大小寫無關：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，如果未設置此屬性，那么當前logger將會繼承上級的級別。--><!--使用mybatis的時候，sql語句是debug下才會打印，而這里我們只配置了info，所以想要查看sql語句的話，有以下兩種操作：第一種把<root level="INFO">改成<root level="DEBUG">這樣就會打印sql，不過這樣日志那邊會出現很多其他消息第二種就是單獨給mapper下目錄配置DEBUG模式，代碼如下，這樣配置sql語句會打印，其他還是正常DEBUG級別：<logger name="cn.zysheep.mapper" level="INFO" />--><!--結合spring多環境使用 開發環境:打印控制臺--><springProfile name="dev"><!--root節點是必選節點，用來指定最基礎的日志輸出級別，只有一個level屬性level:用來設置打印級別，大小寫無關：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，不寫level屬性,默認是DEBUG可以包含零個或多個appender元素。--><root level="INFO"><appender-ref ref="CONSOLE" /><appender-ref ref="INFO_FILE" /><appender-ref ref="WARN_FILE" /><appender-ref ref="ERROR_FILE" /></root></springProfile><!--結合spring多環境使用:生產環境:輸出到文件--><springProfile name="pro"><root level="INFO"><appender-ref ref="ERROR_FILE" /><appender-ref ref="WARN_FILE" /></root></springProfile>
</configuration>

TraceIdUtil操作工具類

/*** <p>traceId工具類</P>**/
public class TraceIdUtil {public static final String TRACE_ID = "traceId";/*** 當traceId為空時，顯示的traceId。隨意。*/private static final String DEFAULT_TRACE_ID = "0";/*** 設置traceId*/public static void setTraceId(String traceId) {//如果參數為空，則設置默認traceIdtraceId = StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;//將traceId放到MDC中MDC.put(TRACE_ID, traceId);}/*** 獲取traceId*/public static String getTraceId() {//獲取String traceId = MDC.get(TRACE_ID);//如果traceId為空，則返回默認值return StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;}/*** 判斷traceId為默認值*/public static Boolean defaultTraceId(String traceId) {return DEFAULT_TRACE_ID.equals(traceId);}/*** 生成traceId*/public static String genTraceId() {return UUID.randomUUID().toString();}/*** 判斷traceId為默認值*/public static void removeTraceId() {MDC.clear();}
}

TraceIdFilter自定義過濾器

/*** <p>traceId過濾器,用于設置traceId</P>**/
@WebFilter(urlPatterns = "/*", filterName = "traceIdFilter")
@Order(1)
public class TraceIdFilter extends GenericFilterBean {public static Logger logger = LoggerFactory.getLogger(TraceIdFilter.class);@Overridepublic void doFilter(ServletRequest request, ServletResponse response, FilterChain filterChain) throws IOException, ServletException {//traceId初始化initTraceId((HttpServletRequest) request);//執行后續過濾器long st = System.currentTimeMillis();try {filterChain.doFilter(request, response);} finally {long et = System.currentTimeMillis();logger.info("請求地址:{},耗時(ms):{}", ((HttpServletRequest) request).getRequestURI(), (et - st));TraceIdUtil.removeTraceId();}}/*** traceId初始化*/private void initTraceId(HttpServletRequest request) {//嘗試獲取http請求中的traceIdString traceId = request.getParameter("traceId");//如果當前traceId為空或者為默認traceId，則生成新的traceIdif (StringUtils.isBlank(traceId) || TraceIdUtil.defaultTraceId(traceId)){traceId = TraceIdUtil.genTraceId();}//設置traceIdTraceIdUtil.setTraceId(traceId);}@Overridepublic void destroy() {TraceIdUtil.removeTraceId();}
}

GlobalExceptionHandler全局異常處理類

@Slf4j
@RestControllerAdvice
public class GlobalExceptionHandler {@ExceptionHandler(Exception.class)public R<String> otherExceptionHandler(Exception ex, HttpServletRequest request) {log.warn("Exception:", ex);return R.result(ExceptionCode.SYSTEM_BUSY.getCode(), StringUtils.EMPTY, ExceptionCode.SYSTEM_BUSY.getMsg()).setPath(request.getRequestURI());}
}

TraceIdAspect切面

@Component
@Aspect
@Order
public class TraceIdAspect {/*** 切點:* 1、所有controller包及其子包下的所有方法* 2、所有GlobalExceptionHandler類中的所有方法*/@Pointcut("execution(public * cn.zysheep.controller..*.*(..)) || execution(* cn.zysheep.exception.GlobalExceptionHandler.*(..))")public void pointCut() {}@Around("pointCut()")public Object around(ProceedingJoinPoint pjp) throws Throwable {Object object = pjp.proceed();if (object instanceof R) {((R<?>) object).setTraceId(TraceIdUtil.getTraceId());}return object;}
}

UserController

@RestController
@RequestMapping("/user")
public class UserController {private static final Logger log = LoggerFactory.getLogger(UserController.class);@GetMapping(value = "query")public R findByPage() throws InterruptedException {log.info("開始執行查詢用戶業務");TimeUnit.MILLISECONDS.sleep(500);log.info("查詢用戶業務執行結束");return R.success();}@GetMapping("/exception")public R exception()  {log.info("開始執行業務");//這里模擬了一個錯誤，10/0，會報錯System.out.println(10 / 0);log.info("業務執行結束");return R.success();}
}

測試驗證

多線程處理

MDCUtil工具類

/*** <p>* 封裝MDC用于向線程池傳遞* </p>*/
public class MDCUtil {// 設置MDC中的traceId值，不存在則新生成，針對不是子線程的情況，// 如果是子線程，MDC中traceId不為nullpublic static void setTraceIdIfAbsent() {if (MDC.get(TraceIdUtil.TRACE_ID) == null) {MDC.put(TraceIdUtil.TRACE_ID, TraceIdUtil.getTraceId());}}public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {return () -> {if (CollectionUtils.isEmpty(context)) {MDC.clear();} else {MDC.setContextMap(context);}setTraceIdIfAbsent();try {return callable.call();} finally {//清除子線程的，避免內存溢出，就和ThreadLocal.remove()一個原因MDC.clear();}};}public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {return () -> {if (context == null) {MDC.clear();} else {MDC.setContextMap(context);}setTraceIdIfAbsent();try {runnable.run();} finally {MDC.clear();}};}public static void setMDCContextMap(final Map<String, String> context) {if (CollectionUtils.isEmpty(context)) {MDC.clear();} else {MDC.setContextMap(context);}}
}

ThreadPoolMdcWrapper

public class ThreadPoolMdcWrapper extends ThreadPoolTaskExecutor {public ThreadPoolMdcWrapper() {}@Overridepublic void execute(Runnable task) {super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic void execute(Runnable task, long startTimeout) {super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);}@Overridepublic <T> Future<T> submit(Callable<T> task) {return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic Future<?> submit(Runnable task) {return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic ListenableFuture<?> submitListenable(Runnable task) {return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}@Overridepublic <T> ListenableFuture<T> submitListenable(Callable<T> task) {return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));}
}

ContextTransferTaskDecorator

public class ContextTransferTaskDecorator implements TaskDecorator {@Overridepublic Runnable decorate(Runnable runnable) {Map<String, String> context = MDC.getCopyOfContextMap();RequestAttributes requestAttributes = RequestContextHolder.currentRequestAttributes();return () -> {try {MDC.setContextMap(context);RequestContextHolder.setRequestAttributes(requestAttributes);runnable.run();} finally {MDC.clear();RequestContextHolder.resetRequestAttributes();}};}
}

ThreadPoolConfig

@Configuration
public class ThreadPoolConfig {@Bean("poolTaskExecutor")public ThreadPoolTaskExecutor threadPoolTaskExecutor() {ThreadPoolTaskExecutor taskExecutor = new ThreadPoolMdcWrapper();//核心線程數，默認為1taskExecutor.setCorePoolSize(5);//最大線程數，默認為Integer.MAX_VALUEtaskExecutor.setMaxPoolSize(10);//隊列最大長度，一般需要設置值>=notifyScheduledMainExecutor.maxNum；默認為Integer.MAX_VALUEtaskExecutor.setQueueCapacity(200);//線程池維護線程所允許的空閑時間，默認為60staskExecutor.setKeepAliveSeconds(60);taskExecutor.setThreadNamePrefix("sif-async-executor-");//線程池對拒絕任務（無線程可用）的處理策略taskExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());taskExecutor.setTaskDecorator(new ContextTransferTaskDecorator());// 初始化線程池taskExecutor.initialize();return  taskExecutor;}
}

UserController

@RestController
@RequestMapping("/user")
public class UserController {private static final Logger log = LoggerFactory.getLogger(UserController.class);@Resource(name = "poolTaskExecutor")private ThreadPoolTaskExecutor threadPoolExecutor;@GetMapping("/t1")public R test1(){log.info("開始....");CompletableFuture.runAsync(() ->{log.info("異步中....");}, threadPoolExecutor);log.info("結束....");return R.success();}@GetMapping("/t2")public R test2(){log.info("開始....");threadPoolExecutor.execute(() ->{log.info("線程池中....");});log.info("結束....");return R.success();}
}

測試驗證