不會(huì)吧，你還不會(huì)用RequestId看日志 ?
在日常的后端開發(fā)工作中，最常見的操作之一就是看日志排查問題，對于大項(xiàng)目一般使用類似ELK的技術(shù)棧統(tǒng)一搜集日志，小項(xiàng)目就直接把日志打印到日志文件。那不管對于大項(xiàng)目或者小項(xiàng)目，查看日志都需要通過某個(gè)關(guān)鍵字進(jìn)行搜索，從而快速定位到異常日志的位置來進(jìn)一步排查問題。
對于后端初學(xué)者來說，日志的關(guān)鍵字可能就是直接打印某個(gè)業(yè)務(wù)的說明加上業(yè)務(wù)標(biāo)識(shí)，如果出現(xiàn)問題直接搜索對應(yīng)的說明或者標(biāo)識(shí)。例如下單場景，可能就直接打印:創(chuàng)建訂單，訂單編號(hào):xxxx，當(dāng)有問題的時(shí)候，則直接搜索訂單編號(hào)或者創(chuàng)建訂單。在這種方式下，經(jīng)常會(huì)搜索出多條日志，增加問題的排查時(shí)長。
所以，今天我們就來說一說這個(gè)關(guān)鍵字的設(shè)計(jì)，這里我們使用RequestId進(jìn)行精確定位問題日志的位置從而解決問題。
需求
目標(biāo)： 幫助開發(fā)快速定位日志位置
思路：當(dāng)前端進(jìn)行一次請求的時(shí)候，在進(jìn)行業(yè)務(wù)邏輯處理之前我們需要生成一個(gè)唯一的RequestId，在業(yè)務(wù)邏輯處理過程中涉及到日志打印我們都需要帶上這個(gè)RequestId，最后響應(yīng)給前端的數(shù)據(jù)結(jié)構(gòu)同樣需要帶上RequestId。 這樣，每次請求都會(huì)有一個(gè)RequestId，當(dāng)某個(gè)接口異常則通過前端反饋的RequestId，后端即可快速定位異常的日志位置。
總結(jié)下我們的需求：
一次請求生成一次
RequestId，并且RequestId唯一一次請求響應(yīng)給前端，都需要返回
RequestId字段，接口正常、業(yè)務(wù)異常、系統(tǒng)異常，都需要返回該字段一次請求在控制臺(tái)或者日志文件打印的日志，都需要顯示
RequestId一次請求的入?yún)⒑统鰠⒍夹枰蛴?/p>
對于異步操作，需要在異步線程的日志同樣顯示
RequestId
實(shí)現(xiàn)
實(shí)現(xiàn)生成和存儲(chǔ)
RequestId的工具類
public class RequestIdUtils {
? ?private static final ThreadLocal<UUID> requestIdHolder = new ThreadLocal<>();
? ?private RequestIdUtils() {
? ?}
? ?public static void generateRequestId() {
? ? ? ?requestIdHolder.set(UUID.randomUUID());
? ?}
? ?public static void generateRequestId(UUID uuid) {
? ? ? ?requestIdHolder.set(uuid);
? ?}
? ?public static UUID getRequestId() {
? ? ? ?return (UUID)requestIdHolder.get();
? ?}
? ?public static void removeRequestId() {
? ? ? ?requestIdHolder.remove();
? ?}
}
因?yàn)槲覀円淮握埱髸?huì)生成一次RequestId，并且RequestId唯一，所以這里我們使用使用UUID來生成RequestId，并且用ThreadLocal進(jìn)行存儲(chǔ)。
實(shí)現(xiàn)一個(gè)AOP，攔截所有的Controller的方法，這里是主要的處理邏輯
@Aspect
@Order
@Slf4j
public class ApiMessageAdvisor {
? ?@Around("execution(public * org.anyin.gitee.shiro.controller..*Controller.*(..))")
? ?public Object invokeAPI(ProceedingJoinPoint pjp) {
? ? ? ?String apiName = this.getApiName(pjp);
? ? ? ?// 生成RequestId
? ? ? ?String requestId = this.getRequestId();
? ? ? ?// 配置日志文件打印 REQUEST_ID
? ? ? ?MDC.put("REQUEST_ID", requestId);
? ? ? ?Object returnValue = null;
? ? ? ?try{
? ? ? ? ? ?// 打印請求參數(shù)
? ? ? ? ? ?this.printRequestParam(apiName, pjp);
? ? ? ? ? ?returnValue = pjp.proceed();
? ? ? ? ? ?// 處理RequestId
? ? ? ? ? ?this.handleRequestId(returnValue);
? ? ? ?}catch (BusinessException ex){
? ? ? ? ? ?// 業(yè)務(wù)異常
? ? ? ? ? ?returnValue = this.handleBusinessException(apiName, ex);
? ? ? ?}catch (Throwable ex){
? ? ? ? ? ?// 系統(tǒng)異常 ? ? ? ?
? ? ? ? ? ?returnValue = this.handleSystemException(apiName, ex);
? ? ? ?}finally {
? ? ? ? ? ?// 打印響應(yīng)參數(shù)
? ? ? ? ? ?this.printResponse(apiName, returnValue);
? ? ? ? ? ?RequestIdUtils.removeRequestId();
? ? ? ? ? ?MDC.clear();
? ? ? ?}
? ? ? ?return returnValue;
? ?}
? ?/**
? ? * 處理系統(tǒng)異常
? ? * @param apiName 接口名稱
? ? * @param ex 系統(tǒng)異常
? ? * @return 返回參數(shù)
? ? */
? ?private Response handleSystemException(String apiName, Throwable ex){
? ? ? ?log.error("@Meet unknown error when do " + apiName + ":" + ex.getMessage(), ex);
? ? ? ?Response response = new Response(BusinessCodeEnum.UNKNOWN_ERROR.getCode(), BusinessCodeEnum.UNKNOWN_ERROR.getMsg());
? ? ? ?response.setRequestId(RequestIdUtils.getRequestId().toString());
? ? ? ?return response;
? ?}
? ?/**
? ? * 處理業(yè)務(wù)異常
? ? * @param apiName 接口名稱
? ? * @param ex 業(yè)務(wù)異常
? ? * @return 返回參數(shù)
? ? */
? ?private Response handleBusinessException(String apiName, BusinessException ex){
? ? ? ?log.error("@Meet error when do " + apiName + "[" + ex.getCode() + "]:" + ex.getMsg(), ex);
? ? ? ?Response response = new Response(ex.getCode(), ex.getMsg());
? ? ? ?response.setRequestId(RequestIdUtils.getRequestId().toString());
? ? ? ?return response;
? ?}
? ?/**
? ? * 填充RequestId
? ? * @param returnValue 返回參數(shù)
? ? */
? ?private void handleRequestId(Object returnValue){
? ? ? ?if(returnValue instanceof Response){
? ? ? ? ? ?Response response = (Response)returnValue;
? ? ? ? ? ?response.setRequestId(RequestIdUtils.getRequestId().toString());
? ? ? ?}
? ?}
? ?/**
? ? * 打印響應(yīng)參數(shù)信息
? ? * @param apiName 接口名稱
? ? * @param returnValue 返回值
? ? */
? ?private void printResponse(String apiName, Object returnValue){
? ? ? ?if (log.isInfoEnabled()) {
? ? ? ? ? ?log.info("@@{} done, response: {}", apiName, JSONUtil.toJsonStr(returnValue));
? ? ? ?}
? ?}
? ?/**
? ? * 打印請求參數(shù)信息
? ? * @param apiName 接口名稱
? ? * @param pjp 切點(diǎn)
? ? */
? ?private void printRequestParam(String apiName, ProceedingJoinPoint pjp){
? ? ? ?Object[] args = pjp.getArgs();
? ? ? ?if(log.isInfoEnabled() && args != null&& args.length > 0){
? ? ? ? ? ?for(Object o : args) {
? ? ? ? ? ? ? ?if(!(o instanceof HttpServletRequest) && !(o instanceof HttpServletResponse) && !(o instanceof CommonsMultipartFile)) {
? ? ? ? ? ? ? ? ? ?log.info("@@{} started, request: {}", apiName, JSONUtil.toJsonStr(o));
? ? ? ? ? ? ? ?}
? ? ? ? ? ?}
? ? ? ?}
? ?}
? ?/**
? ? * 獲取RequestId
? ? * 優(yōu)先從header頭獲取，如果沒有則自己生成
? ? * @return RequestId
? ? */
? ?private String getRequestId(){
? ? ? ?// 因?yàn)槿绻芯W(wǎng)關(guān)，則一般會(huì)從網(wǎng)關(guān)傳遞過來，所以優(yōu)先從header頭獲取
? ? ? ?ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
? ? ? ?if(attributes != null && StringUtils.hasText(attributes.getRequest().getHeader("x-request-id"))) {
? ? ? ? ? ?HttpServletRequest request = attributes.getRequest();
? ? ? ? ? ?String requestId = request.getHeader("x-request-id");
? ? ? ? ? ?UUID uuid = UUID.fromString(requestId);
? ? ? ? ? ?RequestIdUtils.generateRequestId(uuid);
? ? ? ? ? ?return requestId;
? ? ? ?}
? ? ? ?UUID existUUID = RequestIdUtils.getRequestId();
? ? ? ?if(existUUID != null){
? ? ? ? ? ?return existUUID.toString();
? ? ? ?}
? ? ? ?RequestIdUtils.generateRequestId();
? ? ? ?return RequestIdUtils.getRequestId().toString();
? ?}
? ?/**
? ? * 獲取當(dāng)前接口對應(yīng)的類名和方法名
? ? * @param pjp 切點(diǎn)
? ? * @return apiName
? ? */
? ?private String getApiName(ProceedingJoinPoint pjp){
? ? ? ?String apiClassName = pjp.getTarget().getClass().getSimpleName();
? ? ? ?String methodName = pjp.getSignature().getName();
? ? ? ?return apiClassName.concat(":").concat(methodName);
? ?}
}
簡單說明：
對于
RequestId的獲取方法getRequestId，我們優(yōu)先從header頭獲取，有網(wǎng)關(guān)的場景下一般會(huì)從網(wǎng)關(guān)傳遞過來；其次判斷是否已經(jīng)存在，如果存在則直接返回，這里是為了兼容有過濾器并且在過濾器生成了RequestId的場景；最后之前2中場景都未找到RequestId，則自己生成，并且返回MDC.put("REQUEST_ID", requestId)在我們生成RequestId之后，需要設(shè)置到日志系統(tǒng)中，這樣子日志文件才能打印RequestIdprintRequestParam和printResponse是打印請求參數(shù)和響應(yīng)參數(shù)，如果是高并發(fā)或者參數(shù)很多的場景下，最好不要打印handleRequestId、handleBusinessException、handleSystemException這三個(gè)方法分別是在接口正常、接口業(yè)務(wù)異常、接口系統(tǒng)異常的場景下設(shè)置RequestId
日志文件配置
<contextName>logback</contextName>
<springProperty scope="context" name="level" source="logging.level.root"/>
<springProperty scope="context" name="path" source="logging.file.path"/>
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
? ?<Target>System.out</Target>
? <filter class="ch.qos.logback.classic.filter.ThresholdFilter" >
? ? ? ?<level>DEBUG</level>
? ?</filter>
? ?<encoder>
? ? ? ?<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{REQUEST_ID}] [%thread] [%-5level] [%logger{0}:%L] : %msg%n</pattern>
? ?</encoder>
</appender>
<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
? ?<file>${path}</file>
? ?<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
? ? ? ?<fileNamePattern>${path}.%d{yyyy-MM-dd}.zip</fileNamePattern>
? ?</rollingPolicy>
? ?<encoder>
? ? ? ?<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{REQUEST_ID}] [%thread] [%-5level] [%logger{0}:%L] : %msg%n</pattern>
? ?</encoder>
</appender>
<root level="${level}">
? ?<appender-ref ref="console"/>
? ?<appender-ref ref="file"/>
</root>
這里是一個(gè)簡單的日志格式配置文件，主要是關(guān)注[%X{REQUEST_ID}], 這里主要是把RequestId在日志文件中打印出來
解決線程異步場景下
RequestId的打印問題
public class MdcExecutor implements Executor {
? ?private Executor executor;
? ?public MdcExecutor(Executor executor) {
? ? ? ?this.executor = executor;
? ?}
? ?@Override
? ?public void execute(Runnable command) {
? ? ? ?final String requestId = MDC.get("REQUEST_ID");
? ? ? ?executor.execute(() -> {
? ? ? ? ? ?MDC.put("REQUEST_ID", requestId);
? ? ? ? ? ?try {
? ? ? ? ? ? ? ?command.run();
? ? ? ? ? ?} finally {
? ? ? ? ? ? ? ?MDC.remove("REQUEST_ID");
? ? ? ? ? ?}
? ? ? ?});
? ?}
}
這里是一個(gè)簡單的代理模式，代理了Executor，在真正執(zhí)行的run方法之前設(shè)置RequestId到日志系統(tǒng)中，這樣子異步線程的日志同樣可以打印我們想要的RequestId
測試效果
登錄效果
正常的業(yè)務(wù)處理
發(fā)生業(yè)務(wù)異常
發(fā)生系統(tǒng)異常
異步線程
最后
通過以上騷操作，同學(xué)，你知道怎么使用RequestId看日志了嗎？
還不懂的話，請看完整源碼地址：
