Spring Boot 使用AOP統一處理Web請求日誌

AOP爲Aspect Oriented Programming的縮寫，意爲：面向切面編程，經過預編譯方式和運行期動態代理實現程序功能的統一維護的一種技術。AOP是Spring框架中的一個重要內容，它經過對既有程序定義一個切入點，而後在其先後切入不一樣的執行內容，好比常見的有：打開數據庫鏈接/關閉數據庫鏈接、打開事務/關閉事務、記錄日誌等。基於AOP不會破壞原來程序邏輯，所以它能夠很好的對業務邏輯的各個部分進行隔離，從而使得業務邏輯各部分之間的耦合度下降，提升程序的可重用性，同時提升了開發的效率。

下面主要講兩個內容，一個是如何在Spring Boot中引入Aop功能，二是如何使用Aop作切面去統一處理Web請求的日誌。

準備工做

由於須要對web請求作切面來記錄日誌，因此先引入web模塊，並建立一個簡單的hello請求的處理。

• pom.xml中引入web模塊

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

• 實現一個簡單請求處理：經過傳入name參數，返回「hello xxx」的功能。

@RestController
public class HelloController {

    @RequestMapping(value = "/hello", method = RequestMethod.GET)
    @ResponseBody
    public String hello(@RequestParam String name) {
        return "Hello " + name;
    }

}

下面，咱們能夠對上面的/hello請求，進行切面日誌記錄。

引入AOP依賴

在Spring Boot中引入AOP就跟引入其餘模塊同樣，很是簡單，只須要在pom.xml中加入以下依賴：

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

在完成了引入AOP依賴包後，通常來講並不須要去作其餘配置。也許在Spring中使用過註解配置方式的人會問是否須要在程序主類中增長@EnableAspectJAutoProxy來啓用，實際並不須要。

能夠看下面關於AOP的默認配置屬性，其中spring.aop.auto屬性默認是開啓的，也就是說只要引入了AOP依賴後，默認已經增長了@EnableAspectJAutoProxy。

# AOP
spring.aop.auto=true # Add @EnableAspectJAutoProxy.
spring.aop.proxy-target-class=false # Whether subclass-based (CGLIB) proxies are to be created (true) as
 opposed to standard Java interface-based proxies (false).

而當咱們須要使用CGLIB來實現AOP的時候，須要配置spring.aop.proxy-target-class=true，否則默認使用的是標準Java的實現。

實現Web層的日誌切面

實現AOP的切面主要有如下幾個要素：

• 使用@Aspect註解將一個java類定義爲切面類
• 使用@Pointcut定義一個切入點，能夠是一個規則表達式，好比下例中某個package下的全部函數，也能夠是一個註解等。
• 根據須要在切入點不一樣位置的切入內容
  • 使用@Before在切入點開始處切入內容
  • 使用@After在切入點結尾處切入內容
  • 使用@AfterReturning在切入點return內容以後切入內容（能夠用來對處理返回值作一些加工處理）
  • 使用@Around在切入點先後切入內容，並本身控制什麼時候執行切入點自身的內容
  • 使用@AfterThrowing用來處理當切入內容部分拋出異常以後的處理邏輯

@Aspect
@Component
public class WebLogAspect {

    private Logger logger = Logger.getLogger(getClass());

    @Pointcut("execution(public * com.didispace.web..*.*(..))")
    public void webLog(){}

    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        // 接收到請求，記錄請求內容
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        // 記錄下請求內容
        logger.info("URL : " + request.getRequestURL().toString());
        logger.info("HTTP_METHOD : " + request.getMethod());
        logger.info("IP : " + request.getRemoteAddr());
        logger.info("CLASS_METHOD : " + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        logger.info("ARGS : " + Arrays.toString(joinPoint.getArgs()));

    }

    @AfterReturning(returning = "ret", pointcut = "webLog()")
    public void doAfterReturning(Object ret) throws Throwable {
        // 處理完請求，返回內容
        logger.info("RESPONSE : " + ret);
    }

}

能夠看上面的例子，經過@Pointcut定義的切入點爲com.didispace.web包下的全部函數（對web層全部請求處理作切入點），而後經過@Before實現，對請求內容的日誌記錄（本文只是說明過程，能夠根據須要調整內容），最後經過@AfterReturning記錄請求返回的對象。

經過運行程序並訪問：http://localhost:8080/hello?name=didi，能夠得到下面的日誌輸出

2016-05-19 13:42:13,156  INFO WebLogAspect:41 - URL : http://localhost:8080/hello
2016-05-19 13:42:13,156  INFO WebLogAspect:42 - HTTP_METHOD : http://localhost:8080/hello
2016-05-19 13:42:13,157  INFO WebLogAspect:43 - IP : 0:0:0:0:0:0:0:1
2016-05-19 13:42:13,160  INFO WebLogAspect:44 - CLASS_METHOD : com.didispace.web.HelloController.hello
2016-05-19 13:42:13,160  INFO WebLogAspect:45 - ARGS : [didi]
2016-05-19 13:42:13,170  INFO WebLogAspect:52 - RESPONSE:Hello didi

優化：AOP切面中的同步問題

在WebLogAspect切面中，分別經過doBefore和doAfterReturning兩個獨立函數實現了切點頭部和切點返回後執行的內容，若咱們想統計請求的處理時間，就須要在doBefore處記錄時間，並在doAfterReturning處經過當前時間與開始處記錄的時間計算獲得請求處理的消耗時間。

那麼咱們是否能夠在WebLogAspect切面中定義一個成員變量來給doBefore和doAfterReturning一塊兒訪問呢？是否會有同步問題呢？

的確，直接在這裏定義基本類型會有同步問題，因此咱們能夠引入ThreadLocal對象，像下面這樣進行記錄：

@Aspect
@Component
public class WebLogAspect {

    private Logger logger = Logger.getLogger(getClass());

    ThreadLocal<Long> startTime = new ThreadLocal<>();

    @Pointcut("execution(public * com.didispace.web..*.*(..))")
    public void webLog(){}

    @Before("webLog()")
    public void doBefore(JoinPoint joinPoint) throws Throwable {
        startTime.set(System.currentTimeMillis());

        // 省略日誌記錄內容
    }

    @AfterReturning(returning = "ret", pointcut = "webLog()")
    public void doAfterReturning(Object ret) throws Throwable {
        // 處理完請求，返回內容
        logger.info("RESPONSE : " + ret);
        logger.info("SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));
    }


}

優化：AOP切面的優先級

因爲經過AOP實現，程序獲得了很好的解耦，可是也會帶來一些問題，好比：咱們可能會對Web層作多個切面，校驗用戶，校驗頭信息等等，這個時候常常會碰到切面的處理順序問題。

因此，咱們須要定義每一個切面的優先級，咱們須要@Order(i)註解來標識切面的優先級。i的值越小，優先級越高。假設咱們還有一個切面是CheckNameAspect用來校驗name必須爲didi，咱們爲其設置@Order(10)，而上文中WebLogAspect設置爲@Order(5)，因此WebLogAspect有更高的優先級，這個時候執行順序是這樣的：

• 在@Before中優先執行@Order(5)的內容，再執行@Order(10)的內容
• 在@After和@AfterReturning中優先執行@Order(10)的內容，再執行@Order(5)的內容

因此咱們能夠這樣子總結：

• 在切入點前的操做，按order的值由小到大執行
• 在切入點後的操做，按order的值由大到小執行