1. 程式人生 > >SpringBoot 配置 AOP 列印日誌

SpringBoot 配置 AOP 列印日誌

在專案開發中,日誌系統是必不可少的,用AOP在Web的請求做入參和出參的引數列印,同時對異常進行日誌列印,避免重複的手寫日誌,完整案例見文末原始碼。

一、Spring AOP

AOP(Aspect-Oriented Programming,面向切面程式設計),它利用一種"橫切"的技術,將那些多個類的共同行為封裝到一個可重用的模組。便於減少系統的重複程式碼,降低模組之間的耦合度,並有利於未來的可操作性和可維護性。

AOP中有以下概念:

  • Aspect(切面):宣告類似於Java中的類宣告,在Aspect中會包含一些Pointcut及相應的Advice。
  • Joint point(連線點):表示在程式中明確定義的點。包括方法的呼叫、對類成員的訪問等。
  • Pointcut(切入點):表示一個組Joint point,如方法名、引數型別、返回型別等等。
  • Advice(通知):Advice定義了在Pointcut裡面定義的程式點具體要做的操作,它通過(beforearoundafter(returnthrow)、finally來區別實在每個Joint point之前、之後還是執行 前後要呼叫的程式碼。
  • Before:在執行方法前呼叫Advice,比如請求介面之前的登入驗證。
  • Around:在執行方法前後呼叫Advice,這是最常用的方法。
  • After:在執行方法後呼叫Adviceafterreturn是方法正常返回後呼叫,after\throw
    是方法丟擲異常後呼叫。
  • Finally:方法呼叫後執行Advice,無論是否丟擲異常還是正常返回。
  • AOP proxyAOP proxy也是Java物件,是由AOP框架建立,用來完成上述動作,AOP物件通常可以通過JDK dynamic proxy完成,或者使用CGLIb完成。
  • Weaving:實現上述切面程式設計的程式碼織入,可以在編譯時刻,也可以在執行時刻,Spring和其它大多數Java框架都是在執行時刻生成代理。

二、專案示例

當然,在使用該案例之前,如果需要了解日誌配置相關,可參考 SpringBoot 非同步輸出 Logback 日誌, 本文就不再概述了。

2.1 在pom引入依賴

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

    <dependency>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-aop</artifactId>
    </dependency>
    <!-- 分析客戶端資訊的工具類-->
    <dependency>
        <groupId>eu.bitwalker</groupId>
        <artifactId>UserAgentUtils</artifactId>
        <version>1.20</version>
    </dependency>
    <!-- lombok -->
    <dependency>
        <groupId>org.projectlombok</groupId>
        <artifactId>lombok</artifactId>
        <scope>1.8.4</scope>
    </dependency>
</dependencies>

2.2 Controller 切面:WebLogAspect

@Aspect
@Component
@Slf4j
public class WebLogAspect {

    /**
     * 進入方法時間戳
     */
    private Long startTime;
    /**
     * 方法結束時間戳(計時)
     */
    private Long endTime;

    public WebLogAspect() {
    }


    /**
     * 定義請求日誌切入點,其切入點表示式有多種匹配方式,這裡是指定路徑
     */
    @Pointcut("execution(public * cn.van.log.aop.controller.*.*(..))")
    public void webLogPointcut() {
    }

    /**
     * 前置通知:
     * 1. 在執行目標方法之前執行,比如請求介面之前的登入驗證;
     * 2. 在前置通知中設定請求日誌資訊,如開始時間,請求引數,註解內容等
     *
     * @param joinPoint
     * @throws Throwable
     */
    @Before("webLogPointcut()")
    public void doBefore(JoinPoint joinPoint) {

        // 接收到請求,記錄請求內容
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        //獲取請求頭中的User-Agent
        UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent"));
        //列印請求的內容
        startTime = System.currentTimeMillis();
        log.info("請求開始時間:{}" + LocalDateTime.now());
        log.info("請求Url : {}" + request.getRequestURL().toString());
        log.info("請求方式 : {}" + request.getMethod());
        log.info("請求ip : {}" + request.getRemoteAddr());
        log.info("請求方法 : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        log.info("請求引數 : {}" + Arrays.toString(joinPoint.getArgs()));
        // 系統資訊
        log.info("瀏覽器:{}", userAgent.getBrowser().toString());
        log.info("瀏覽器版本:{}", userAgent.getBrowserVersion());
        log.info("作業系統: {}", userAgent.getOperatingSystem().toString());
    }

    /**
     * 返回通知:
     * 1. 在目標方法正常結束之後執行
     * 1. 在返回通知中補充請求日誌資訊,如返回時間,方法耗時,返回值,並且儲存日誌資訊
     *
     * @param ret
     * @throws Throwable
     */
    @AfterReturning(returning = "ret", pointcut = "webLogPointcut()")
    public void doAfterReturning(Object ret) throws Throwable {
        endTime = System.currentTimeMillis();
        log.info("請求結束時間:{}" + LocalDateTime.now());
        log.info("請求耗時:{}" + (endTime - startTime));
        // 處理完請求,返回內容
        log.info("請求返回 : {}" + ret);
    }

    /**
     * 異常通知:
     * 1. 在目標方法非正常結束,發生異常或者丟擲異常時執行
     * 1. 在異常通知中設定異常資訊,並將其儲存
     *
     * @param throwable
     */
    @AfterThrowing(value = "webLogPointcut()", throwing = "throwable")
    public void doAfterThrowing(Throwable throwable) {
        // 儲存異常日誌記錄
        log.error("發生異常時間:{}" + LocalDateTime.now());
        log.error("丟擲異常:{}" + throwable.getMessage());
    }
}

2.3 編寫測試

@RestController
@RequestMapping("/log")
public class LogbackController {

    /**
     * 測試正常請求
     * @param msg
     * @return
     */
    @GetMapping("/{msg}")
    public String getMsg(@PathVariable String msg) {
        return "request msg : " + msg;
    }

    /**
     * 測試拋異常
     * @return
     */
    @GetMapping("/test")
    public String getException(){
        // 故意造出一個異常
        Integer.parseInt("abc123");
        return "success";
    }
}

2.4 @Before@AfterReturning部分也可使用以下程式碼替代

    /**
     * 在執行方法前後呼叫Advice,這是最常用的方法,相當於@Before和@AfterReturning全部做的事兒
     * @param pjp
     * @return
     * @throws Throwable
     */
    @Around("webLogPointcut()")
    public Object doAround(ProceedingJoinPoint pjp) throws Throwable {
        // 接收到請求,記錄請求內容
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        //獲取請求頭中的User-Agent
        UserAgent userAgent = UserAgent.parseUserAgentString(request.getHeader("User-Agent"));
        //列印請求的內容
        startTime = System.currentTimeMillis();
        log.info("請求Url : {}" , request.getRequestURL().toString());
        log.info("請求方式 : {}" , request.getMethod());
        log.info("請求ip : {}" , request.getRemoteAddr());
        log.info("請求方法 : " , pjp.getSignature().getDeclaringTypeName() , "." , pjp.getSignature().getName());
        log.info("請求引數 : {}" , Arrays.toString(pjp.getArgs()));
    // 系統資訊
        log.info("瀏覽器:{}", userAgent.getBrowser().toString());
        log.info("瀏覽器版本:{}",userAgent.getBrowserVersion());
        log.info("作業系統: {}", userAgent.getOperatingSystem().toString());
        // pjp.proceed():當我們執行完切面程式碼之後,還有繼續處理業務相關的程式碼。proceed()方法會繼續執行業務程式碼,並且其返回值,就是業務處理完成之後的返回值。
        Object ret = pjp.proceed();
        log.info("請求結束時間:"+ LocalDateTime.now());
        log.info("請求耗時:{}" , (System.currentTimeMillis() - startTime));
        // 處理完請求,返回內容
        log.info("請求返回 : " , ret);
        return ret;
    }

三、 測試

3.1 請求入口LogbackController.java

@RestController
@RequestMapping("/log")
public class LogbackController {

    /**
     * 測試正常請求
     * @param msg
     * @return
     */
    @GetMapping("/normal/{msg}")
    public String getMsg(@PathVariable String msg) {
        return msg;
    }

    /**
     * 測試拋異常
     * @return
     */
    @GetMapping("/exception/{msg}")
    public String getException(@PathVariable String msg){
        // 故意造出一個異常
        Integer.parseInt("abc123");
        return msg;
    }
}

3.2 測試正常請求

開啟瀏覽器,訪問http://localhost:8082/log/normal/hello

日誌列印如下:

[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [65] [INFO ] 請求開始時間:2019-02-24T22:37:50.892
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [66] [INFO ] 請求Url : http://localhost:8082/log/normal/hello
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [67] [INFO ] 請求方式 : GET
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [68] [INFO ] 請求ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [69] [INFO ] 請求方法 : 
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [70] [INFO ] 請求引數 : [hello]
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [72] [INFO ] 瀏覽器:CHROME
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [73] [INFO ] 瀏覽器版本:76.0.3809.100
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [74] [INFO ] 作業系統: MAC_OS_X
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [88] [INFO ] 請求結束時間:2019-02-24T22:37:50.901
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [89] [INFO ] 請求耗時:14
[2019-02-24 22:37:50.050] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-1] [91] [INFO ] 請求返回 : hello

3.3 測試異常情況

訪問:http://localhost:8082/log/exception/hello

[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [65] [INFO ] 請求開始時間:2019-02-24T22:39:57.728
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [66] [INFO ] 請求Url : http://localhost:8082/log/exception/hello
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [67] [INFO ] 請求方式 : GET
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [68] [INFO ] 請求ip : 0:0:0:0:0:0:0:1
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [69] [INFO ] 請求方法 : 
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [70] [INFO ] 請求引數 : [hello]
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [72] [INFO ] 瀏覽器:CHROME
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [73] [INFO ] 瀏覽器版本:76.0.3809.100
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [74] [INFO ] 作業系統: MAC_OS_X
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [104] [ERROR] 發生異常時間:2019-02-24T22:39:57.731
[2019-02-24 22:39:57.057] [cn.van.log.aop.aspect.WebLogAspect] [http-nio-8082-exec-9] [105] [ERROR] 丟擲異常:For input string: "abc123"
[2019-02-24 22:39:57.057] [org.apache.juli.logging.DirectJDKLog] [http-nio-8082-exec-9] [175] [ERROR] Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NumberFormatException: For input string: "abc123"] with root cause
java.lang.NumberFormatException: For input string: "abc123"

四、原始碼

4.1 示例程式碼

  1. Github 示例程式碼