項目請求日志詳細調用打印

項目中經常需要通過日志定位線上問題,詳細的日志有助於快速定位問題,下面通過aop和MDC解決.

打印詳細請求信息

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

基本請求信息

// 使用目標類進行日志打印
logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass().getName());
ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
HttpServletRequest request = attributes.getRequest();
// 打印請求相關參數
logger.info("========================================== Start ==========================================");
// 打印請求 url
logger.info("URL            : {}", request.getRequestURL().toString());
// 打印 Http method
logger.info("HTTP Method    : {}", request.getMethod());
// 打印調用 controller 的全路徑以及執行方法
logger.info("Class Method   : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
// 打印請求的 IP
logger.info("IP             : {}", (request.getHeader("X-Forwarded-For") == null) ? request.getRemoteAddr() : request.getHeader("X-Forwarded-For"));
// 打印請求Cookie
logger.info("Cookie         : {}", cookie(request.getCookies()));
// 打印請求入參 https://blog.csdn.net/weixin_44130081/article/details/98847575
logger.info("Request Args   : {}", Arrays.toString(joinPoint.getArgs()));

• 打印請求IP: 支持代理IP打印
• 打印請求入參: 入參沒有使用json工具(GSON和FastJSON)進行封裝,當請求方法有HttpServletResponse參數,比如做文件上傳或者excel導入時,會造成內存溢出.可以使用Arrays.toString打印

異常信息打印

// 打印異常
logger.info("{}      : {}", e.getClass().getName(), e.getMessage());

出參和請求耗時打印

long startTime = System.currentTimeMillis();
Object result = proceedingJoinPoint.proceed();
// 打印出參
GsonBuilder gsonBuilder = new GsonBuilder();
// 處理null值 https://www.jianshu.com/p/83eb1b2bc119
gsonBuilder.serializeSpecialFloatingPointValues();
Gson gson = gsonBuilder.create();
logger.info("Response Args  : {}", gson.toJson(result));
// 執行耗時
logger.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);

日志追蹤

日志調用追蹤

一次請求,后台會產生一連串的方法調用.如何判斷在一次請求中,都調用那些方法,找出對應的日志記錄,就需要對打印日志進行線程標記.

1. 在resources目錄下新建: logback-spring.xml,修改<pattern>規則,示例:

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{trace_uuid}] [%level] [%thread] [%c:%L] - %msg%n</pattern>

• {trace_uuid}: 唯一編碼

2. 在請求執行前,存入當前線程的MDC值.比如使用aop的@Before

@Before("webLog()")
public void doBefore(JoinPoint joinPoint) {
    // 開始打印請求日志
    MDC.put("trace_uuid", UUID.randomUUID().toString());// 加入trace追蹤
}

方法調用追蹤

在維護老項目或接手一個新項目時,一個方法可能在很多處被調用,對分析不熟悉的業務邏輯造成很大的困難.方法調用鏈可以清楚顯示該方法被調用的路徑

1. 自定義注解@LogTrace

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target({ElementType.TYPE, ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface LogTrace {
}

2. aop對注解進行解析

@After("@annotation(com.lyf.annotation.LogTrace)")
public void log_trace(JoinPoint joinPoint) {
    JavaLangAccess access = SharedSecrets.getJavaLangAccess();
    Throwable throwable = new Throwable();
    int depth = access.getStackTraceDepth(throwable);
    Class clazz = joinPoint.getTarget().getClass();
    String targetName = clazz.getSimpleName();
    String methodName = joinPoint.getSignature().getName();
    String target = targetName + "." + methodName;
    logger.info("====== StackTrace: " + target + " ======");
    for (int i = depth - 1; i > 0; i--) {//從1開始不顯示當前工具類調用
        StackTraceElement ste = access.getStackTraceElement(throwable, i);
//            for(int j=1;j<depth-i;j++){
//                System.out.print("\t");//縮進
//            }
        String className = ste.getClassName();
        if (className.contains("lyf") && !className.contains("$$") && !className.contains("aop")) {
            logger.info(String.format("[%s.%s:%s]", ste.getClassName(), ste.getMethodName(), ste.getLineNumber()));
        }
    }
    logger.info("====== StackTrace: " + target + " ======");
}

3. 使用示例

@LogTrace
public User queryUser (Integer id){
    return userMapper.queryById(id);
}

完整代碼

logback-spring.xml

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <!-- 控制台輸出日志 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{trace_uuid}] [%level] [%c:%L] - %msg%n</pattern>
        </encoder>
    </appender>
    <!--每天生成一個日志文件，保存30天的日志文件。-->
    <appender name="DayFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>logs/log.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logs/log.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{trace_uuid}] [%level] [%thread] [%c:%L] - %msg%n</pattern>
        </encoder>
    </appender>
    <!--指定logger name為包名或類全名 指定級別 additivity設置是否傳遞到root logger -->
    <logger name="slf4j" level="INFO" additivity="false">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="DayFile"/>
    </logger>
    <!--slf4j2包下的類在ERROR級別時候傳遞到root logger中-->
    <logger name="slf4j2" level="ERROR"/>
    <!--根logger控制-->
    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="DayFile"/>
    </root>
</configuration>

WebLogAspect.java

package com.lyf.aop;

import com.google.gson.Gson;
import com.google.gson.GsonBuilder;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;
import sun.misc.JavaLangAccess;
import sun.misc.SharedSecrets;

import javax.servlet.http.Cookie;
import javax.servlet.http.HttpServletRequest;
import java.util.Arrays;
import java.util.UUID;

@Aspect
@Component
public class WebLogAspect {

    private static Logger logger;

    /**
     * 以 controller 包下定義的所有請求為切入點
     */
    @Pointcut("execution(public * com.lyf.controller..*.*(..))")
    public void webLog() {
    }

    /**
     * 在切點之前織入
     *
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) {
        // 開始打印請求日志
        MDC.put("trace_uuid", UUID.randomUUID().toString());// 加入trace追蹤
        // 使用目標類進行日志打印
        logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass().getName());
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        // 打印請求相關參數
        logger.info("========================================== Start ==========================================");
        // 打印請求 url
        logger.info("URL            : {}", request.getRequestURL().toString());
        // 打印 Http method
        logger.info("HTTP Method    : {}", request.getMethod());
        // 打印調用 controller 的全路徑以及執行方法
        logger.info("Class Method   : {}.{}", joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName());
        // 打印請求的 IP
        logger.info("IP             : {}", (request.getHeader("X-Forwarded-For") == null) ? request.getRemoteAddr() : request.getHeader("X-Forwarded-For"));
        // 打印請求Cookie
        logger.info("Cookie         : {}", cookie(request.getCookies()));
        // 打印請求入參 https://blog.csdn.net/weixin_44130081/article/details/98847575
        logger.info("Request Args   : {}", Arrays.toString(joinPoint.getArgs()));
    }

    /**
     * 在切點之后織入
     *
     * @throws Throwable
     */
    @After("webLog()")
    public void doAfter() throws Throwable {
        logger.info("=========================================== End ===========================================");
        // 每個請求之間空一行
        logger.info("☜☝☞");
    }


    /**
     * 在切點異常之后織入
     *
     * @throws Throwable
     */
    @AfterThrowing(value = "webLog()", throwing = "e")
    public void doAfterThrowing(Exception e) throws Throwable {
// 打印異常
        logger.info("{}      : {}", e.getClass().getName(), e.getMessage());
    }

    /**
     * 環繞
     *
     * @param proceedingJoinPoint
     * @return
     * @throws Throwable
     */
    @Around("webLog()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object result = proceedingJoinPoint.proceed();
        // 打印出參
        GsonBuilder gsonBuilder = new GsonBuilder();
        // 處理null值 https://www.jianshu.com/p/83eb1b2bc119
        gsonBuilder.serializeSpecialFloatingPointValues();
        Gson gson = gsonBuilder.create();
        logger.info("Response Args  : {}", gson.toJson(result));
        // 執行耗時
        logger.info("Time-Consuming : {} ms", System.currentTimeMillis() - startTime);
        return result;
    }

    private String cookie(Cookie[] cookies) {
        StringBuilder stringBuilder = new StringBuilder();
        if (cookies != null && cookies.length > 0) {
            stringBuilder.append("[");
            for (int i = 0; i < cookies.length; i++) {
                if (i > 0) {
                    stringBuilder.append(", ");
                }
                stringBuilder.append(cookies[i].getName()).append("=").append(cookies[i].getValue());
            }
            stringBuilder.append("]");
        }
        return stringBuilder.toString();
    }

    @After("@annotation(com.lyf.annotation.LogTrace)")
    public void log_trace(JoinPoint joinPoint) {
        JavaLangAccess access = SharedSecrets.getJavaLangAccess();
        Throwable throwable = new Throwable();
        int depth = access.getStackTraceDepth(throwable);
        Class clazz = joinPoint.getTarget().getClass();
        String targetName = clazz.getSimpleName();
        String methodName = joinPoint.getSignature().getName();
        String target = targetName + "." + methodName;
        logger.info("====== StackTrace: " + target + " ======");
        for (int i = depth - 1; i > 0; i--) {//從1開始不顯示當前工具類調用
            StackTraceElement ste = access.getStackTraceElement(throwable, i);
//            for(int j=1;j<depth-i;j++){
//                System.out.print("\t");//縮進
//            }
            String className = ste.getClassName();
            if (className.contains("lyf") && !className.contains("$$") && !className.contains("aop")) {
                logger.info(String.format("[%s.%s:%s]", ste.getClassName(), ste.getMethodName(), ste.getLineNumber()));
            }
        }
        logger.info("====== StackTrace: " + target + " ======");
    }
}