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

原文：http://blog.didispace.com/springbootaoplog/

 

 

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

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

以下所有操作基於chapter4-2-2工程進行。

准備工作

因為需要對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的值由大到小執行