MDC 的必要性
日志框架
日志框架成熟的也比較多：
我們沒有必要重復造輪子，一般是建議和 slf4j 進行整合，便於后期替換為其他框架。
日志的使用
基本上所有的應用都需要打印日志，但並不是每一個開發都會輸出日志。
主要有下面的問題：
（1）日志太少，出問題時無法定位問題
（2）日志太多，查找問題很麻煩，對服務器磁盤也是很大的壓力
（3）日志級別控制不合理
（4）沒有一個唯一標識貫穿整個調用鏈路
我們本次主要談一談第四個問題。
為什么需要唯一標識
對於最常見的 web 應用，每一次請求都可以認為新開了一個線程。
在並發高一點的情況，我們的日志會出現穿插的情況。就是我們看日志時，發現出現不屬於當前請求的日志，看起來就會特別累。所以需要一個過濾條件，可以將請求的整個生命周期連接起來，也就是我們常說的 traceId。
我們看日志的時候，比如 traceId='202009021658001'，那么執行如下的命令即可：
grep 202009021658001 app.log
就可以將這個鏈路對應的日志全部過濾出來。
那么應該如何實現呢？
實現思路
（1）生成一個唯一標識 traceId
這個比較簡單，比如 UUID 之類的就行，保證唯一即可。
（2）輸出日志時，打印這個 traceId
於是很自然的就會有下面的代碼：
logger.info("traceId: {} Controller 層請求參數為: {}", traceId, req);
缺陷
很多項目都是這種實現方式，這種實現方式有幾個問題：
（1）需要參數傳遞
比如從 controller =》biz =》service，就因為一個 traceId，我們所有的方法都需要多一個參數，用來接受這個值。
非常的不優雅
（2）需要輸出 traceId
每次都要記得輸出這個值，或者就無法關聯。
如果有個別方法忘記輸出，那我們根據 traceId 查看日志就會變得很奇怪。
（3）復雜度提高
我們每一個日志都需要區輸出這個額外的 traceId，作為一個懶人，不樂意區寫這個代碼。
那么，有什么方法可以解決這個問題嗎？
slf4j 的 MDC 就是為了解決這個問題而存在的。
MDC 的應用場景
程序中，日志打印時我們有時需要跟蹤整個調用鏈路。
最常見的做法，就是將一個屬性，比如 traceId 從最外層一致往下傳遞。
導致每個方法都會多出這個參數，卻只是為了打印一個標識，很不推薦。
MDC 就是為了這個場景使用的。
簡單例子
普通實現版本
在方法調用前后，手動設置。
本文展示 aop 的方式，原理一樣，更加靈活方便。代碼也更加優雅。
基於 aop 的方式
定義攔截器
import com.baomidou.mybatisplus.toolkit.IdWorker;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
/**
* 日志攔截器
* @author binbin.hou
* @date 2018/12/7
*/
@Component
@Aspect
public class LogAspect {
/**
* 限額限日志次的 trace id
*/
private static final String TRACE_ID = "TRACE_ID";
/**
* 攔截入口下所有的 public方法
*/
@Pointcut("execution(public * com.github.houbb..*(..))")
public void pointCut() {
}
/**
* 攔截處理
*
* @param point point 信息
* @return result
* @throws Throwable if any
*/
@Around("pointCut()")
public Object around(ProceedingJoinPoint point) throws Throwable {
//添加 MDC
MDC.put(TRACE_ID, IdWorker.getIdStr());
Object result = point.proceed();
//移除 MDC
MDC.remove(TRACE_ID);
return result;
}
}
IdWorker.getIdStr() 只是用來生成一個唯一標識，你可以使用 UUID 等來替代。
更多生成唯一標識的方法，參考：
這個 AOP 的切面一般建議放在調用的入口。
（1）controller 層入口
（2）mq 消費入口
（3）外部 rpc 請求入口
定義 logback.xml
定義好了 MDC，接下來我們在日志配置文件中使用即可。
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%X{TRACE_ID}] [%thread] %logger{50} - %msg%n</pattern>
</encoder>
[%X{TRACE_ID}] 就是我們系統中需要使用的唯一標識，配置好之后日志中就會將這個標識打印出來。
如果不存在，就是直接空字符串，也不影響。
對於已經存在的系統
現象
如果有一個已經存在已久的項目，原始的打印日志，都會從最上層把訂單編號一直傳遞下去，你會怎么做？
也是這樣，把一個標識號從最開始一直傳遞到最底層嗎？
當然不是的。
你完全可以做的更好。
原理
我們知道 MDC 的原理就是在當前的線程中放置一個屬性，這個屬性在同一個線程中是唯一且共享的。
所以不同的線程之間不會相互干擾。
那么我們對於比較舊的系統，可以采取最簡單的方式：
提供一個工具類，可以獲取當前線程的訂單號。當然，你需要在一個地方將這個值設置到當前線程，一般是方法入口的地方。
更好的方式
你可以提供一個打印日志的工具類，復寫常見的日志打印方法。
將日志 traceId 信息等隱藏起來，對於開發是不可見的。
實現方式 ThreadLocal
不再贅述，參見 ThreadLocal
基礎的工具類
import org.slf4j.MDC;
/**
* 日志工具類
* @author binbin.hou
*/
public final class LogUtil {
private LogUtil(){}
/**
* trace id
*/
private static final String TRACE_ID = "TRACE_ID";
/**
* 設置 traceId
* @param traceId traceId
*/
public static void setTraceId(final String traceId) {
MDC.put(TRACE_ID, traceId);
}
/**
* 移除 traceId
*/
public static void removeTraceId() {
MDC.remove(TRACE_ID);
}
/**
* 獲取批次號
* @return 批次號
*/
public static String getTraceId() {
return MDC.get(TRACE_ID);
}
}
對於異步的處理
spring 異步
參見 async 異步
異步的 traceId 處理
在異步的時候，就會另起一個線程。
建議異步的時候，將原來父類線程的唯一標識(traceId) 當做參數傳遞下去，然后將這個參數設置為子線程的 traceId。
不依賴 MDC
MDC 的限制
MDC 雖然使用起來比較方便，但是畢竟是 slf4j 為我們實現的一個工具。
其原理就是基於 ThreadLocal 保存基於線程隔離標識。
知道這一點，其實我們可以自己實現一個類似 MDC 的功能，滿足不同的應用場景。
實現思路
（1）生成日志唯一標識
（2）基於 ThreadLocal 保存唯一的線程標識
（3）基於注解+AOP
@Around("@annotation(trace)")
public Object trace(ProceedingJoinPoint joinPoint, Trace trace) {
// 生成 id
// 設置 id 到當前線程
Object result = joinPoint.proceed();
// 移除 id
return result;
}
（4）如何使用 id
最簡單的方式，就是我們創建一個工具類 LogUtil。
對於常見的方法進行重寫，然后日志輸出統一調用這個方法。
缺點：日志中的輸出 class 類會看不出來，當然可以通過獲取方法來解決
優點：實現簡單，便於后期拓展和替換。
開源工具
auto-log 是一款為 java 設計的自動日志監控框架。
創作目的
經常會寫一些工具，有時候手動加一些日志很麻煩，引入 spring 又過於大材小用。
所以希望從從簡到繁實現一個工具，便於平時使用。
特性
-
基於注解+字節碼，配置靈活
-
自動適配常見的日志框架
-
支持編程式的調用
-
支持注解式，完美整合 spring
-
支持整合 spring-boot
-
支持慢日志閾值指定，耗時，入參，出參，異常信息等常見屬性指定
-
支持 traceId 特性
快速開始
maven 引入
<dependency>
<group>com.github.houbb</group>
<artifact>auto-log-core</artifact>
<version>0.0.8</version>
</dependency>
入門案例
UserService userService = AutoLogHelper.proxy(new UserServiceImpl());
userService.queryLog("1");
- 日志如下
[INFO] [2020-05-29 16:24:06.227] [main] [c.g.h.a.l.c.s.i.AutoLogMethodInterceptor.invoke] - public java.lang.String com.github.houbb.auto.log.test.service.impl.UserServiceImpl.queryLog(java.lang.String) param is [1]
[INFO] [2020-05-29 16:24:06.228] [main] [c.g.h.a.l.c.s.i.AutoLogMethodInterceptor.invoke] - public java.lang.String com.github.houbb.auto.log.test.service.impl.UserServiceImpl.queryLog(java.lang.String) result is result-1
代碼
其中方法實現如下：
- UserService.java
public interface UserService {
String queryLog(final String id);
}
- UserServiceImpl.java
直接使用注解 @AutoLog 指定需要打日志的方法即可。
public class UserServiceImpl implements UserService {
@Override
@AutoLog
public String queryLog(String id) {
return "result-"+id;
}
}
TraceId 的例子
代碼
UserService service = AutoLogProxy.getProxy(new UserServiceImpl());
service.traceId("1");
其中 traceId 方法如下：
@AutoLog
@TraceId
public String traceId(String id) {
return id+"-1";
}
測試效果
信息: [ba7ddaded5a644e5a58fbd276b6657af] <traceId>入參: [1].
信息: [ba7ddaded5a644e5a58fbd276b6657af] <traceId>出參：1-1.
其中 ba7ddaded5a644e5a58fbd276b6657af 就是對應的 traceId，可以貫穿整個 thread 周期，便於我們日志查看。
注解說明
@AutoLog
核心注解 @AutoLog 的屬性說明如下：
| 屬性 | 類型 | 默認值 | 說明 |
|---|---|---|---|
| param | boolean | true | 是否打印入參 |
| result | boolean | true | 是否打印出參 |
| costTime | boolean | false | 是否打印耗時 |
| exception | boolean | true | 是否打印異常 |
| slowThresholdMills | long | -1 | 當這個值大於等於 0 時，且耗時超過配置值，會輸出慢日志 |
| description | string | "" | 方法描述，默認選擇方法名稱 |
@TraceId
@TraceId 放在需要設置 traceId 的方法上，比如 Controller 層，mq 的消費者，rpc 請求的接受者等。
| 屬性 | 類型 | 默認值 | 說明 |
|---|---|---|---|
| id | Class | 默認為 uuid | traceId 的實現策略 |
| putIfAbsent | boolean | false | 是否在當前線程沒有值的時候才設置值 |
spring 整合使用
完整示例參考 SpringServiceTest
注解聲明
使用 @EnableAutoLog 啟用自動日志輸出
@Configurable
@ComponentScan(basePackages = "com.github.houbb.auto.log.test.service")
@EnableAutoLog
public class SpringConfig {
}
測試代碼
@ContextConfiguration(classes = SpringConfig.class)
@RunWith(SpringJUnit4ClassRunner.class)
public class SpringServiceTest {
@Autowired
private UserService userService;
@Test
public void queryLogTest() {
userService.queryLog("1");
}
}
- 輸出結果
信息: public java.lang.String com.github.houbb.auto.log.test.service.impl.UserServiceImpl.queryLog(java.lang.String) param is [1]
五月 30, 2020 12:17:51 下午 com.github.houbb.auto.log.core.support.interceptor.AutoLogMethodInterceptor info
信息: public java.lang.String com.github.houbb.auto.log.test.service.impl.UserServiceImpl.queryLog(java.lang.String) result is result-1
五月 30, 2020 12:17:51 下午 org.springframework.context.support.GenericApplicationContext doClose
springboot 整合使用
maven 引入
<dependency>
<groupId>com.github.houbb</groupId>
<artifactId>auto-log-springboot-starter</artifactId>
<version>0.0.8</version>
</dependency>
只需要引入 jar 即可，其他的什么都不用配置。
使用方式和 spring 一致。
測試
@Autowired
private UserService userService;
@Test
public void queryLogTest() {
userService.query("spring-boot");
}
開源地址
