問題描述
最近經(jīng)常做線上問題的排查，而排查問題用得最多的方式是查看日志留荔，但是在現(xiàn)有系統(tǒng)中府树，各種無關(guān)日志穿行其中，導(dǎo)致我沒辦法快速的找出用戶在一次請求中所有的日志偎蘸。
問題分析
我們沒辦法快速定位用戶在一次請求中對應(yīng)的所有日志庄蹋，或者說是定位某個(gè)用戶操作的所有日志，那是因?yàn)槲覀冊谳敵龅娜罩镜臅r(shí)候沒把請求的唯一標(biāo)示或者說是用戶身份標(biāo)示輸出到我們的日志中迷雪，導(dǎo)致我們沒辦法根據(jù)一個(gè)請求或者用戶身份標(biāo)示來做日志的過濾限书。所以我們在記錄日志的是后把請求的唯一標(biāo)示（sessionId）或者身份標(biāo)示（userId） 記錄到日志中這個(gè)問題就可以得到很好的解決了。
解決方案
在每次請求的時(shí)候章咧，獲取到請求的sessionId（或者自己生成一個(gè)偽sessionId）倦西，并在每次輸出log的時(shí)候?qū)⑦@個(gè)sessionId輸出到日志中。這個(gè)方式實(shí)現(xiàn)簡單赁严，代碼侵入型強(qiáng)扰柠，每次輸出都會(huì)多輸出一個(gè)sessionId參數(shù)，工作量大疼约，但是可控粒度高卤档。
我們使用Logback的MDC機(jī)制，日志模板中加入sessionId格式程剥。在日志輸出格式中指定輸出sessionId劝枣。如：
%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n
這種方式工作量小，代碼侵入小，易擴(kuò)展哨免，但是可控粒度低茎活。
方案說明
第一種方案很簡單，也很容易實(shí)現(xiàn)琢唾，就是在輸出日志的時(shí)候多輸出一個(gè)參數(shù)载荔，如：
logger.info("sessionId: {}, message: {}", sessionId, "日志信息");
我們這里主要說一下第二種方式的實(shí)現(xiàn)。
實(shí)現(xiàn)思路采桃，這里以Spring MVC為例：
新建一個(gè)日志攔截器懒熙，在攔截所有請求，在處理請求前將sessionId放到MDC中普办，在處理完請求后清除MDC的內(nèi)容工扎。這里就解決了80%的問題。
在原來版本中新起線程時(shí)MDC會(huì)自動(dòng)將父線程的MDC內(nèi)容復(fù)制給子線程衔蹲，因?yàn)镸DC內(nèi)部使用的是InheritableThreadLocal肢娘，但是因?yàn)樾阅軉栴}在最新的版本中被取消了，所以子線程不會(huì)自動(dòng)獲取到父線程的MDC內(nèi)容舆驶。官方建議我們在父線程新建子線程之前調(diào)用MDC.getCopyOfContextMap()方法將MDC內(nèi)容取出來傳給子線程橱健，子線程在執(zhí)行操作前先調(diào)用MDC.setContextMap()方法將父線程的MDC內(nèi)容設(shè)置到子線程。
設(shè)置日志輸出格式
%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] -%5p ${PID:-} [%15.15t] %-40.40logger{39} : %m%n
攔截器 LogInterceptor
package com.xiaolyuh.interceptors;
import org.slf4j.MDC;
import org.springframework.web.servlet.ModelAndView;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;
/**
* 日志攔截器組件沙廉，在輸出日志中加上sessionId
*
* @author yuhao.wang3
*/
public class LogInterceptor extends HandlerInterceptorAdapter {
/**
* 會(huì)話ID
*/
private final static String SESSION_KEY = "sessionId";
@Override
public void afterCompletion(HttpServletRequest arg0, HttpServletResponse arg1, Object arg2, Exception arg3)
throws Exception {
// 刪除SessionId
MDC.remove(SESSION_KEY);
}
@Override
public void postHandle(HttpServletRequest arg0, HttpServletResponse arg1,
Object arg2, ModelAndView arg3) throws Exception {
}
@Override
public boolean preHandle(HttpServletRequest request,
HttpServletResponse response, Object handler) throws Exception {
// 設(shè)置SessionId
String token = UUID.randomUUID().toString().replace("-", "");
MDC.put(SESSION_KEY, token);
return true;
}
}
注冊攔截器
/**
* WEB MVC配置類
*
* @author yuhao.wang3
*/
@Configuration
public class WebMvcConfigurer extends WebMvcConfigurerAdapter {
/**
* 把我們的攔截器注入為bean
*
* @return
*/
@Bean
public HandlerInterceptor logInterceptor() {
return new LogInterceptor();
}
/**
* 注冊攔截器
*
* @param registry
*/
@Override
public void addInterceptors(InterceptorRegistry registry) {
// addPathPatterns 用于添加攔截規(guī)則, 這里假設(shè)攔截 /url 后面的全部鏈接
// excludePathPatterns 用戶排除攔截
registry.addInterceptor(logInterceptor()).addPathPatterns("/**");
super.addInterceptors(registry);
}
}
擴(kuò)展ThreadPoolTaskExecutor線程池
擴(kuò)展ThreadPoolTaskExecutor線程池的主要目的是實(shí)現(xiàn)將父線程的MDC內(nèi)容復(fù)制給子線程拘荡。
package com.xiaolyuh.utils;
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import java.util.Map;
/**
* 這是{@link ThreadPoolTaskExecutor}的一個(gè)簡單替換，可以在每個(gè)任務(wù)之前設(shè)置子線程的MDC數(shù)據(jù)撬陵。
* <p/>
* 在記錄日志的時(shí)候珊皿，一般情況下我們會(huì)使用MDC來存儲(chǔ)每個(gè)線程的特有參數(shù)，如身份信息等巨税，以便更好的查詢?nèi)罩尽? * 但是Logback在最新的版本中因?yàn)樾阅軉栴}蟋定，不會(huì)自動(dòng)的將MDC的內(nèi)存?zhèn)鹘o子線程。所以Logback建議在執(zhí)行異步線程前
* 先通過MDC.getCopyOfContextMap()方法將MDC內(nèi)存獲取出來垢夹，再傳給線程溢吻。
* 并在子線程的執(zhí)行的最開始調(diào)用MDC.setContextMap(context)方法將父線程的MDC內(nèi)容傳給子線程。
* <p>
* https://logback.qos.ch/manual/mdc.html
*
* @author yuhao.wang3
*/
public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
/**
* 所有線程都會(huì)委托給這個(gè)execute方法果元，在這個(gè)方法中我們把父線程的MDC內(nèi)容賦值給子線程
* https://logback.qos.ch/manual/mdc.html#managedThreads
*
* @param runnable
*/
@Override
public void execute(Runnable runnable) {
// 獲取父線程MDC中的內(nèi)容促王，必須在run方法之前，否則等異步線程執(zhí)行的時(shí)候有可能MDC里面的值已經(jīng)被清空了而晒，這個(gè)時(shí)候就會(huì)返回null
Map<String, String> context = MDC.getCopyOfContextMap();
super.execute(() -> run(runnable, context));
}
/**
* 子線程委托的執(zhí)行方法
*
* @param runnable {@link Runnable}
* @param context 父線程MDC內(nèi)容
*/
private void run(Runnable runnable, Map<String, String> context) {
// 將父線程的MDC內(nèi)容傳給子線程
MDC.setContextMap(context);
try {
// 執(zhí)行異步操作
runnable.run();
} finally {
// 清空MDC內(nèi)容
MDC.clear();
}
}
}
擴(kuò)展Hystrix
擴(kuò)展Hystrix線程池隔離支持日志鏈路跟蹤
/**
* Hystrix線程池隔離支持日志鏈路跟蹤
*
* @author yuhao.wang3
*/
public class MdcHystrixConcurrencyStrategy extends HystrixConcurrencyStrategy {
@Override
public <T> Callable<T> wrapCallable(Callable<T> callable) {
return new MdcAwareCallable(callable, MDC.getCopyOfContextMap());
}
private class MdcAwareCallable<T> implements Callable<T> {
private final Callable<T> delegate;
private final Map<String, String> contextMap;
public MdcAwareCallable(Callable<T> callable, Map<String, String> contextMap) {
this.delegate = callable;
this.contextMap = contextMap != null ? contextMap : new HashMap();
}
@Override
public T call() throws Exception {
try {
MDC.setContextMap(contextMap);
return delegate.call();
} finally {
MDC.clear();
}
}
}
}
配置Hystrix
@Configuration
public class HystrixConfig {
//用來攔截處理HystrixCommand注解
@Bean
public HystrixCommandAspect hystrixAspect() {
return new HystrixCommandAspect();
}
@PostConstruct
public void init() {
HystrixPlugins.getInstance().registerConcurrencyStrategy(new MdcHystrixConcurrencyStrategy());
}
}
Logback配置
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<property name="CONSOLE_LOG_PATTERN"
value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} [%X{sessionId}] %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
<property name="FILE_LOG_PATTERN"
value="${FILE_LOG_PATTERN:-%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{sessionId}] ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>
<include resource="org/springframework/boot/logging/logback/base.xml"/>
<appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender">
<!-- 不丟失日志.默認(rèn)的,如果隊(duì)列的80%已滿,則會(huì)丟棄TRACT蝇狼、DEBUG、INFO級別的日志 -->
<discardingThreshold>0</discardingThreshold>
<!-- 更改默認(rèn)的隊(duì)列的深度,該值會(huì)影響性能.默認(rèn)值為256 -->
<queueSize>2048</queueSize>
<includeCallerData>true</includeCallerData>
<!-- 添加附加的appender,最多只能添加一個(gè) -->
<appender-ref ref="FILE"/>
</appender>
<logger name="com.xiaolyuh" level="debug" additivity="true"/>
</configuration>
測試類
@Service
public class LogService {
Logger logger = LoggerFactory.getLogger(LogService.class);
public void log() {
logger.debug("==============================================");
ThreadTaskUtils.run(() -> run());
FutureTask<String> futureTask = new FutureTask<String>(() -> call());
ThreadTaskUtils.run(futureTask);
try {
logger.debug("===================: {}", futureTask.get());
} catch (Exception e) {
logger.error(e.getMessage(), e);
}
logger.debug("==============================================");
}
private String call() {
logger.debug("11111111111");
return "3333";
}
public void run() {
logger.debug("222222222222222");
}
}
日志輸出示例
2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.376 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-1] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.377 [a114db8f4be942d891407d57ff74276d] DEBUG 12828 --- [http-nio-80-exec-9] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-5] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-3] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.536 [8657ed4f5267489aa323f9422974002b] DEBUG 12828 --- [http-nio-80-exec-2] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ==============================================
2018-06-02 23:11:02.728 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-2] com.xiaolyuh.service.LogService : 222222222222222
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [MdcThreadPoolTaskExecutor-4] com.xiaolyuh.service.LogService : 11111111111
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ===================: 3333
2018-06-02 23:11:02.729 [e85380fb1554463ca156318b0a3ff7c2] DEBUG 12828 --- [http-nio-80-exec-3] com.xiaolyuh.service.LogService : ==============================================
源碼
https://github.com/wyh-spring-ecosystem-student/spring-boot-student/tree/releases
spring-boot-student-log 工程
