朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP

powerzhuye發表於2018-10-07

標題有點標題黨了,這裡說的容易犯錯不是Spring AOP的錯,是指使用的時候容易犯錯。本文會以一些例子來展開討論AOP的使用以及使用過程中容易出錯的點。

幾句話說清楚AOP

朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP

有關必要術語:

  1. 切面:Aspect,有的地方也叫做方面。切面=切點+增強,表示我們在什麼點切入蛋糕,切入蛋糕後我們以什麼方式來增強這個點。
  2. 切點:Pointcut,類似於查詢表示式,通過在連線點執行查詢表示式來尋找匹配切入點,Spring AOP中預設使用AspjectJ查詢表示式。
  3. 增強:Advice,有的地方也叫做通知。定義了切入切點後增強的方式,增強方式有前、後、環繞等等。Spring AOP中把增強定義為攔截器。
  4. 連線點:Join point,蛋糕所有可以切入的點,對於Spring AOP連線點就是方法執行。

有關使用方式:

  1. Spring AOP API:這種方式是Spring AOP實現的基石。最老的使用方式,在Spring 1.2中的時候用這種API的方式定義AOP。
  2. 註解宣告:使用@AspectJ的@Aspect、@Pointcut等註解來定義AOP。現在基本都使用這種方式來定義,也是官方推薦的方式。
  3. 配置檔案:相比註解宣告方式,配置方式有兩個缺點,一是定義和實現分離了,二是功能上會比註解宣告弱,無法實現全部功能。好處麼就是XML在靈活方面會強一點。
  4. 程式設計動態配置:使用AspectJProxyFactory進行動態配置。可以作為註解方式靜態配置的補充。

有關織入方式:

織入說通俗點就是怎麼把增強程式碼注入到連線點,和被增強的程式碼融入到一起。

  1. 執行時:Spring AOP只支援這種方式。實現上有兩種方式,一是JDK動態代理,通過反射實現,只支援對實現介面的類進行代理,二是CGLIB動態位元組碼注入方式實現代理,沒有這個限制。Spring 3.2之後的版本已經包含了CGLIB,會根據需要選擇合適的方式來使用。
  2. 編譯時:在編譯的時候把增強程式碼注入進去,通過AspjectJ的ajc編譯器實現。實現上有兩種方式,一種是直接使用ajc編譯所有程式碼,還有一種是javac編譯後再進行後處理。
  3. 載入時:在JVM載入型別的時候注入程式碼,也叫做LTW。通過啟動程式的時候通過javaagent代理預設的類載入器實現。

使用Spring AOP實現事務的坑

新建一個模組:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
   xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
   <modelVersion>4.0.0</modelVersion>

   <groupId>me.josephzhu</groupId>
   <artifactId>spring101-aop</artifactId>
   <version>0.0.1-SNAPSHOT</version>
   <packaging>jar</packaging>

   <name>spring101-aop</name>
   <description></description>

   <parent>
      <groupId>me.josephzhu</groupId>
      <artifactId>spring101</artifactId>
      <version>0.0.1-SNAPSHOT</version>
   </parent>

   <dependencies>
      <dependency>
         <groupId>org.springframework.boot</groupId>
         <artifactId>spring-boot-starter-aop</artifactId>
      </dependency>
        <dependency>
            <groupId>org.mybatis.spring.boot</groupId>
            <artifactId>mybatis-spring-boot-starter</artifactId>
            <version>1.3.2</version>
        </dependency>
        <dependency>
            <groupId>com.h2database</groupId>
            <artifactId>h2</artifactId>
        </dependency>
      <dependency>
         <groupId>com.fasterxml.jackson.core</groupId>
         <artifactId>jackson-databind</artifactId>
         <version>2.9.7</version>
      </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
    </dependencies>

</project>
複製程式碼

在這裡我們引入了jackson,以後我們會用來做JSON序列化。引入了mybatis啟動器,以後我們會用mybstis做資料訪問。引入了h2嵌入式資料庫,方便本地測試使用。引入了web啟動器,之後我們還會來測試一下對web專案的Controller進行注入。 先來定義一下我們的測試資料類:

package me.josephzhu.spring101aop;

import lombok.AllArgsConstructor;
import lombok.Data;
import lombok.NoArgsConstructor;

import java.math.BigDecimal;

@Data
@NoArgsConstructor
@AllArgsConstructor
public class MyBean {
    private Long id;
    private String name;
    private Integer age;
    private BigDecimal balance;
}
複製程式碼

然後,我們在resources資料夾下建立schema.sql檔案來初始化h2資料庫:

CREATE TABLE PERSON(
ID BIGINT  PRIMARY KEY AUTO_INCREMENT,
NAME VARCHAR(255),
AGE SMALLINT,
BALANCE DECIMAL
);
複製程式碼

還可以在resources資料夾下建立data.sql來初始化資料:

INSERT INTO PERSON (NAME, AGE, BALANCE) VALUES ('zhuye', 35, 1000);
複製程式碼

這樣程式啟動後就會有一個PERSON表,表裡有一條ID為1的記錄。 通過啟動器使用Mybatis非常簡單,無需進行任何配置,建一個Mapper介面:

package me.josephzhu.spring101aop;

import org.apache.ibatis.annotations.Insert;
import org.apache.ibatis.annotations.Mapper;
import org.apache.ibatis.annotations.Select;

import java.util.List;

@Mapper
public interface DbMapper {
    @Select("SELECT COUNT(0) FROM PERSON")
    int personCount();

    @Insert("INSERT INTO PERSON (NAME, AGE, BALANCE) VALUES ('zhuye', 35, 1000)")
    void personInsertWithoutId();

    @Insert("INSERT INTO PERSON (ID, NAME, AGE, BALANCE) VALUES (1,'zhuye', 35, 1000)")
    void personInsertWithId();

    @Select("SELECT * FROM PERSON")
    List<MyBean> getPersonList();

}
複製程式碼

這裡我們定義了4個方法:

  1. 查詢表中記錄數的方法
  2. 查詢表中所有資料的方法
  3. 帶ID欄位插入資料的方法,由於程式啟動的時候已經初始化了一條資料,如果這裡我們再插入ID為1的記錄顯然會出錯,用來之後測試事務使用
  4. 不帶ID欄位插入資料的方法 為了我們可以觀察到資料庫連線是否被Spring納入事務管理,我們在application.properties配置檔案中設定mybatis的Spring事務日誌級別為DEBUG:
logging.level.org.mybatis.spring.transaction=DEBUG
複製程式碼

現在我們來建立服務介面:

package me.josephzhu.spring101aop;

import java.time.Duration;
import java.util.List;

public interface MyService {
    void insertData(boolean success);
    List<MyBean> getData(MyBean myBean, int count, Duration delay);
}
複製程式碼

定義了插入資料和查詢資料的兩個方法,下面是實現:

package me.josephzhu.spring101aop;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;
import org.springframework.transaction.annotation.Transactional;

import java.time.Duration;
import java.util.List;
import java.util.stream.Collectors;
import java.util.stream.IntStream;

@Service
public class MyServiceImpl implements MyService {

    @Autowired
    private DbMapper dbMapper;

    @Transactional(rollbackFor = Exception.class)
    public void _insertData(boolean success){
        dbMapper.personInsertWithoutId();
        if(!success)
            dbMapper.personInsertWithId();
    }

    @Override
    public void insertData(boolean success) {
        try {
            _insertData(success);
        } catch (Exception ex) {
            ex.printStackTrace();
        }
        System.out.println("記錄數:" + dbMapper.personCount());
    }

    @Override
    public List<MyBean> getData(MyBean myBean, int count, Duration delay) {
        try {
            Thread.sleep(delay.toMillis());
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return IntStream.rangeClosed(1,count)
                .mapToObj(i->new MyBean((long)i,myBean.getName() + i, myBean.getAge(), myBean.getBalance()))
                .collect(Collectors.toList());
    }
}
複製程式碼

getData方法我們就不細說了,只是實現了休眠然後根據傳入的myBean作為模板組裝了count條測試資料返回。我們來重點看一下insertData方法,這就是使用Spring AOP的一個坑了。看上去配置啥的都沒問題,但是_insertData是不能生效自動事務管理的。

我們知道Spring AOP使用代理目標物件方式實現AOP,在從外部呼叫insertData方法的時候其實走的是代理,這個時候事務環繞可以生效,在方法內部我們通過this引用呼叫_insertData方法,雖然方法外部我們設定了Transactional註解,但是由於走的不是代理呼叫,Spring AOP自然無法通過AOP增強為我們做事務管理。

我們來建立主程式測試一下:

package me.josephzhu.spring101aop;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.CommandLineRunner;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.AdviceMode;
import org.springframework.context.annotation.Configuration;
import org.springframework.transaction.annotation.EnableTransactionManagement;

import java.math.BigDecimal;
import java.time.Duration;

@SpringBootApplication
public class Spring101AopApplication implements CommandLineRunner {

   public static void main(String[] args) {
      SpringApplication.run(Spring101AopApplication.class, args);
   }

   @Autowired
   private MyService myService;

   @Override
   public void run(String... args) throws Exception {
      myService.insertData(true);
      myService.insertData(false);
      System.out.println(myService.getData(new MyBean(0L, "zhuye",35, new BigDecimal("1000")),
            5,
            Duration.ofSeconds(1)));
   }
}
複製程式碼

在Runner中,我們使用true和false呼叫了兩次insertData方法。後面一次呼叫肯定會失敗,因為_insert方法中會進行重複ID的資料插入。執行程式後得到如下輸出:

2018-10-07 09:11:44.605  INFO 19380 --- [           main] m.j.s.Spring101AopApplication            : Started Spring101AopApplication in 3.072 seconds (JVM running for 3.74)
2018-10-07 09:11:44.621 DEBUG 19380 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@2126664214 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will not be managed by Spring
2018-10-07 09:11:44.626 DEBUG 19380 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@775174220 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will not be managed by Spring
記錄數:2
2018-10-07 09:11:44.638 DEBUG 19380 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@2084486251 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will not be managed by Spring
2018-10-07 09:11:44.638 DEBUG 19380 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@26418585 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will not be managed by Spring
2018-10-07 09:11:44.642  INFO 19380 --- [           main] o.s.b.f.xml.XmlBeanDefinitionReader      : Loading XML bean definitions from class path resource [org/springframework/jdbc/support/sql-error-codes.xml]
org.springframework.dao.DuplicateKeyException: 
### Error updating database.  Cause: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "PRIMARY KEY ON PUBLIC.PERSON(ID)"; SQL statement:
INSERT INTO PERSON (ID, NAME, AGE, BALANCE) VALUES (1,'zhuye', 35, 1000) [23505-197]
2018-10-07 09:11:44.689 DEBUG 19380 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@529949842 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will not be managed by Spring
記錄數:3
[MyBean(id=1, name=zhuye1, age=35, balance=1000), MyBean(id=2, name=zhuye2, age=35, balance=1000), MyBean(id=3, name=zhuye3, age=35, balance=1000), MyBean(id=4, name=zhuye4, age=35, balance=1000), MyBean(id=5, name=zhuye5, age=35, balance=1000)]
複製程式碼

從日誌的幾處我們都可以得到結論,事務管理沒有生效:

  1. 我們可以看到有類似Connection will not be managed by Spring的提示,說明連線沒有進入Spring的事務管理。
  2. 程式啟動的時候記錄數為1,第一次呼叫insertData方法後記錄數為2,第二次呼叫方法如果事務生效方法會回滾記錄數會維持在2,在輸出中我們看到記錄數最後是3。

那麼,如何解決這個問題呢,有三種方式:

  1. 使用AspjectJ來實現AOP,這種方式是直接修改程式碼的,不是走代理實現的,不會有這個問題,下面我們會詳細說明一下這個過程。
  2. 在程式碼中使用AopContext.currentProxy()來獲得當前的代理進行_insertData方法呼叫。這種方式侵入太強,而且需要被代理類意識到自己是通過代理被訪問,顯然不是合適的方式。
  3. 改造程式碼,使需要事務代理的方法直接呼叫,類似:
@Override
@Transactional(rollbackFor = Exception.class)
public void insertData(boolean success) {
    dbMapper.personInsertWithoutId();
    if(!success)
        dbMapper.personInsertWithId();
}
複製程式碼

這裡還容易犯錯的地方是,這裡不能對異常進行捕獲,否則Spring事務代理無法捕獲到異常也就無法實現回滾。

使用AspectJ靜態織入進行改造

那麼原來這段程式碼如何不改造實現事務呢?可以通過AspjectJ編譯時靜態織入實現。整個配置過程如下: 首先在pom中加入下面的配置:

<build>
       <sourceDirectory>${project.build.directory}/generated-sources/delombok</sourceDirectory>
       <plugins>
      <plugin>
         <groupId>org.springframework.boot</groupId>
         <artifactId>spring-boot-maven-plugin</artifactId>
      </plugin>
           <plugin>
               <groupId>org.projectlombok</groupId>
               <artifactId>lombok-maven-plugin</artifactId>
               <version>1.18.0.0</version>
               <executions>
                   <execution>
                       <phase>generate-sources</phase>
                       <goals>
                           <goal>delombok</goal>
                       </goals>
                   </execution>
               </executions>
               <configuration>
                   <addOutputDirectory>false</addOutputDirectory>
                   <sourceDirectory>src/main/java</sourceDirectory>
               </configuration>
           </plugin>
           <plugin>
               <groupId>org.codehaus.mojo</groupId>
               <artifactId>aspectj-maven-plugin</artifactId>
               <version>1.10</version>
               <configuration>
                   <complianceLevel>1.8</complianceLevel>
                   <source>1.8</source>
                   <aspectLibraries>
                       <aspectLibrary>
                           <groupId>org.springframework</groupId>
                           <artifactId>spring-aspects</artifactId>
                       </aspectLibrary>
                   </aspectLibraries>
               </configuration>
               <executions>
                   <execution>
                       <goals>
                           <goal>compile</goal>
                           <goal>test-compile</goal>
                       </goals>
                   </execution>
               </executions>
           </plugin>
   </plugins>
</build>
複製程式碼

這裡的一個坑是ajc編譯器無法支援lambok,我們需要先使用lombok的外掛在生成原始碼階段對lombok程式碼進行預處理,然後我們再通過aspjectj外掛來編譯程式碼。Pom檔案中還需要加入如下依賴:

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-aspects</artifactId>
</dependency>
複製程式碼

然後需要配置Spring來使用ASPECTJ的增強方式來做事務管理:

@EnableTransactionManagement(mode = AdviceMode.ASPECTJ)
public class Spring101AopApplication implements CommandLineRunner {
複製程式碼

重新使用maven編譯程式碼後可以看到,相關程式碼已經變了樣:

@Transactional(
    rollbackFor = {Exception.class}
)
public void _insertData(boolean success) {
    AnnotationTransactionAspect var10000 = AnnotationTransactionAspect.aspectOf();
    Object[] var3 = new Object[]{this, Conversions.booleanObject(success)};
    var10000.ajc$around$org_springframework_transaction_aspectj_AbstractTransactionAspect$1$2a73e96c(this, new MyServiceImpl$AjcClosure1(var3), ajc$tjp_0);
}

public void insertData(boolean success) {
    try {
        this._insertData(success);
    } catch (Exception var3) {
        var3.printStackTrace();
    }

    System.out.println("記錄數:" + this.dbMapper.personCount());
}
複製程式碼

執行程式可以看到如下日誌:

2018-10-07 09:35:12.360 DEBUG 19459 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@1169317628 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will be managed by Spring
複製程式碼

而且最後輸出的結果是2,說明第二次插入資料整體回滾了。 如果使用IDEA的話還可以配置先由javac編譯再由ajc後處理,具體參見IDEA官網這裡不詳述。

朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP

使用AOP進行事務後處理

我們先使用剛才說的方法3改造一下程式碼,使得Spring AOP可以處理事務(Aspject AOP功能雖然強大但是和Spring結合的不好,所以我們接下去的測試還是使用Spring AOP),刪除aspjectj相關依賴,在IDEA配置回javac編譯器重新編譯專案。本節中我們嘗試建立第一個我們的切面:

package me.josephzhu.spring101aop;

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import org.springframework.transaction.support.TransactionSynchronizationAdapter;
import org.springframework.transaction.support.TransactionSynchronizationManager;

@Aspect
@Component
@Slf4j
class TransactionalAspect extends TransactionSynchronizationAdapter {

    @Autowired
    private DbMapper dbMapper;

    private ThreadLocal<JoinPoint> joinPoint = new ThreadLocal<>();

    @Before("@within(org.springframework.transaction.annotation.Transactional) || @annotation(org.springframework.transaction.annotation.Transactional)")
    public void registerSynchronization(JoinPoint jp) {
        joinPoint.set(jp);
        TransactionSynchronizationManager.registerSynchronization(this);
    }

    @Override
    public void afterCompletion(int status) {
        log.info(String.format("【%s】【%s】事務提交 %s,目前記錄數:%s",
                joinPoint.get().getSignature().getDeclaringType().toString(),
                joinPoint.get().getSignature().toLongString(),
                status == 0 ? "成功":"失敗",
                dbMapper.personCount()));
        joinPoint.remove();
    }
}
複製程式碼

在這裡,我們的切點是所有標記了@Transactional註解的類以及標記了@Transactional註解的方法,我們的增強比較簡單,在事務同步管理器註冊一個回撥方法,用於事務完成後進行額外的處理。這裡的一個坑是Spring如何例項化切面。通過查文件或做實驗可以得知,預設情況下TranscationalAspect是單例的,在多執行緒情況下,可能會有併發,保險起見我們使用ThreadLocal來存放。執行程式碼後可以看到如下輸出:

2018-10-07 10:01:32.384  INFO 19599 --- [           main] m.j.spring101aop.TransactionalAspect     : 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】事務提交 成功,目前記錄數:2
2018-10-07 10:01:32.385 DEBUG 19599 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@1430104337 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will be managed by Spring
2018-10-07 10:01:32.449 DEBUG 19599 --- [           main] o.m.s.t.SpringManagedTransaction         : JDBC Connection [HikariProxyConnection@1430104337 wrapping conn0: url=jdbc:h2:mem:testdb user=SA] will be managed by Spring
2018-10-07 10:01:32.449  INFO 19599 --- [           main] m.j.spring101aop.TransactionalAspect     : 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】事務提交 失敗,目前記錄數:2
複製程式碼

可以看到Spring AOP做了事務管理,我們兩次事務提交第一次成功第二次失敗,失敗後記錄數還是2。這個功能還可以通過Spring的@TransactionalEventListener註解實現,這裡不詳述。

切換JDK代理和CGLIB代理

我們現在注入的是介面,我們知道對於這種情況Spring AOP應該使用的是JDK代理。但是SpringBoot預設開啟了下面的屬性來全域性啟用CGLIB代理:

spring.aop.proxy-target-class=true
複製程式碼

我們嘗試把這個屬性設定成false,然後在剛才的TransationalAspect中的增強方法設定斷點,可以看到這是一個ReflectiveMethodInvocation:

朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP
把配置改為true重新觀察可以看到變為了CglibMethodInvocation:

朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP
我們把開關改為false,然後切換到注入實現,執行程式會得到如下錯誤提示,意思就是我我們走JDK代理的話不能注入實現,需要注入介面:

The bean 'myServiceImpl' could not be injected as a 'me.josephzhu.spring101aop.MyServiceImpl' because it is a JDK dynamic proxy that implements:
	me.josephzhu.spring101aop.MyService
複製程式碼

我們修改我們的MyServiceImpl,去掉實現介面的程式碼和@Override註解,使之成為一個普通的類,重新執行程式可以看到我們的代理方式自動降級為了CGLIB方式(雖然spring.aop.proxy-target-class引數我們現在設定的是false)。

使用AOP無縫實現日誌+異常+打點

現在我們來實現一個複雜點的切面的例子。我們知道,出錯記錄異常資訊,對於方法呼叫記錄打點資訊(如果不知道什麼是打點可以參看《朱曄的網際網路架構實踐心得S1E4:簡單好用的監控六兄弟》),甚至有的時候為了排查問題需要記錄方法的入參和返回,這三個事情是我們經常需要做的和業務邏輯無關的事情,我們可以嘗試使用AOP的方式一鍵切入這三個事情的實現,在業務程式碼無感知的情況下做好監控和打點。 首先實現我們的註解,通過這個註解我們可以細化控制一些功能:

package me.josephzhu.spring101aop;

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

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Metrics {
    /**
     * 是否在成功執行方法後打點
     * @return
     */
    boolean recordSuccessMetrics() default true;

    /**
     * 是否在執行方法出錯時打點
     * @return
     */
    boolean recordFailMetrics() default true;

    /**
     * 是否記錄請求引數
     * @return
     */
    boolean logParameters() default true;

    /**
     * 是否記錄返回值
     * @return
     */
    boolean logReturn() default true;

    /**
     * 是否記錄異常
     * @return
     */
    boolean logException() default true;

    /**
     * 是否遮蔽異常返回預設值
     * @return
     */
    boolean ignoreException() default false;
}
複製程式碼

下面我們就來實現這個切面:

package me.josephzhu.spring101aop;

import com.fasterxml.jackson.databind.ObjectMapper;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestAttributes;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.servlet.http.HttpServletRequest;
import java.lang.annotation.Annotation;
import java.lang.reflect.Method;
import java.time.Duration;
import java.time.Instant;

@Aspect
@Component
@Slf4j
public class MetricsAspect {
    private static ObjectMapper objectMapper = new ObjectMapper();

    @Around("@annotation(me.josephzhu.spring101aop.Metrics) || @within(org.springframework.stereotype.Controller)")
    public Object metrics(ProceedingJoinPoint pjp) throws Throwable {
        //1
        MethodSignature signature = (MethodSignature) pjp.getSignature();
        Metrics metrics;
        String name;
        if (signature.getDeclaringType().isInterface()) {
            Class implClass = pjp.getTarget().getClass();
            Method method = implClass.getMethod(signature.getName(), signature.getParameterTypes());
            metrics = method.getDeclaredAnnotation(Metrics.class);
            name = String.format("【%s】【%s】", implClass.toString(), method.toString());
        } else {
            metrics = signature.getMethod().getAnnotation(Metrics.class);
            name = String.format("【%s】【%s】", signature.getDeclaringType().toString(), signature.toLongString());
        }
        //2
        if (metrics == null)
            metrics = new Metrics() {
                @Override
                public boolean logException() {
                    return true;
                }

                @Override
                public boolean logParameters() {
                    return true;
                }

                @Override
                public boolean logReturn() {
                    return true;
                }

                @Override
                public boolean recordFailMetrics() {
                    return true;
                }

                @Override
                public boolean recordSuccessMetrics() {
                    return true;
                }

                @Override
                public boolean ignoreException() {
                    return false;
                }

                @Override
                public Class<? extends Annotation> annotationType() {
                    return Metrics.class;
                }
            };
        RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
        if (requestAttributes != null) {
            HttpServletRequest request = ((ServletRequestAttributes) requestAttributes).getRequest();
            if (request != null)
                name += String.format("【%s】", request.getRequestURL().toString());
        }
        //3
        if (metrics.logParameters())
            log.info(String.format("【入參日誌】呼叫 %s 的引數是:【%s】", name, objectMapper.writeValueAsString(pjp.getArgs())));
        //4
        Object returnValue;
        Instant start = Instant.now();
        try {
            returnValue = pjp.proceed();
            if (metrics.recordSuccessMetrics())
                log.info(String.format("【成功打點】呼叫 %s 成功,耗時:%s", name, Duration.between(Instant.now(), start).toString()));
        } catch (Exception ex) {
            if (metrics.recordFailMetrics())
                log.info(String.format("【失敗打點】呼叫 %s 失敗,耗時:%s", name, Duration.between(Instant.now(), start).toString()));

            if (metrics.logException())
                log.error(String.format("【異常日誌】呼叫 %s 出現異常!", name), ex);

            if (metrics.ignoreException())
                returnValue = getDefaultValue(signature.getReturnType().toString());
            else
                throw ex;
        }
        //5
        if (metrics.logReturn())
            log.info(String.format("【出參日誌】呼叫 %s 的返回是:【%s】", name, returnValue));
        return returnValue;
    }

    private static Object getDefaultValue(String clazz) {
        if (clazz.equals("boolean")) {
            return false;
        } else if (clazz.equals("char")) {
            return '\u0000';
        } else if (clazz.equals("byte")) {
            return 0;
        } else if (clazz.equals("short")) {
            return 0;
        } else if (clazz.equals("int")) {
            return 0;
        } else if (clazz.equals("long")) {
            return 0L;
        } else if (clazz.equals("flat")) {
            return 0.0F;
        } else if (clazz.equals("double")) {
            return 0.0D;
        } else {
            return null;
        }
    }

}
複製程式碼

看上去程式碼量很多,其實實現比較簡單:

  1. 最關鍵的切點,我們在兩個點切入,一是標記了Metrics註解的方法,二是標記了Controller的類(我們希望實現的目標是對於Controller所有方法預設都加上這個功能,因為這是對外的介面,比較重要)。所以在之後的程式碼中,我們還需要額外對Web程式做一些處理。
  2. 對於@Around我們的引數是ProceedingJoinPoint不是JoinPoint,因為環繞增強允許我們執行方法呼叫。
  3. 第一段程式碼,我們嘗試獲取當前方法的類名和方法名。這裡有一個坑,如果連線點是介面的話,@Metrics的定義需要從實現類(也就是代理的Target)上獲取。作為框架的開發者,我們需要考慮到各種使用方使用的情況,如果有遺留的話就會出現BUG。
  4. 第二段程式碼,是為Web專案準備的,如果我們希望預設為所有的Controller方法做日誌異常打點處理的話,我們需要初始化一個@Metrics註解出來,然後對於Web專案我們可以從上下文中獲取到額外的一些資訊來豐富我們的日誌。
  5. 第三段程式碼,實現的是入參的日誌輸出。
  6. 第四段程式碼,實現的是連線點方法的執行,以及成功失敗的打點,出現異常的時候還會記錄日誌。這裡我們通過日誌方式暫時替代了打點的實現,標準的實現是需要把資訊提交到類似Graphite這樣的時間序列資料庫或對接SpringBoot Actuator。另外,如果開啟忽略異常的話,我們需要把結果替換為返回型別的預設值,並且吃掉異常。
  7. 第五段程式碼,實現了返回值的日誌輸出。 最後,我們修改一下MyServiceImpl的實現,在insertData和getData兩個方法上加入我們的@Metrics註解。執行程式可以看到如下輸出:
2018-10-07 10:47:00.813  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【入參日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 的引數是:【[true]】
2018-10-07 10:47:00.864  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【成功打點】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 成功,耗時:PT-0.048S
2018-10-07 10:47:00.864  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【出參日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 的返回是:【null】
2018-10-07 10:47:00.927  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【入參日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 的引數是:【[false]】
2018-10-07 10:47:01.084  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【失敗打點】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 失敗,耗時:PT-0.156S
2018-10-07 10:47:01.102 ERROR 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【異常日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public void me.josephzhu.spring101aop.MyServiceImpl.insertData(boolean)】 出現異常!
2018-10-07 10:47:01.231  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【入參日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public java.util.List me.josephzhu.spring101aop.MyServiceImpl.getData(me.josephzhu.spring101aop.MyBean,int,java.time.Duration)】 的引數是:【[{"id":0,"name":"zhuye","age":35,"balance":1000},5,{"seconds":1,"zero":false,"nano":0,"units":["SECONDS","NANOS"],"negative":false}]】
2018-10-07 10:47:02.237  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【成功打點】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public java.util.List me.josephzhu.spring101aop.MyServiceImpl.getData(me.josephzhu.spring101aop.MyBean,int,java.time.Duration)】 成功,耗時:PT-1.006S
2018-10-07 10:47:02.237  INFO 19737 --- [           main] me.josephzhu.spring101aop.MetricsAspect  : 【出參日誌】呼叫 【class me.josephzhu.spring101aop.MyServiceImpl】【public java.util.List me.josephzhu.spring101aop.MyServiceImpl.getData(me.josephzhu.spring101aop.MyBean,int,java.time.Duration)】 的返回是:【[MyBean(id=1, name=zhuye1, age=35, balance=1000), MyBean(id=2, name=zhuye2, age=35, balance=1000), MyBean(id=3, name=zhuye3, age=35, balance=1000), MyBean(id=4, name=zhuye4, age=35, balance=1000), MyBean(id=5, name=zhuye5, age=35, balance=1000)]】
[MyBean(id=1, name=zhuye1, age=35, balance=1000), MyBean(id=2, name=zhuye2, age=35, balance=1000), MyBean(id=3, name=zhuye3, age=35, balance=1000), MyBean(id=4, name=zhuye4, age=35, balance=1000), MyBean(id=5, name=zhuye5, age=35, balance=1000)]
複製程式碼

正確實現了引數日誌、異常日誌、成功失敗打點(含耗時統計)等功能。 下面我們建立一個Controller來測試一下是否可以自動切入Controller:

package me.josephzhu.spring101aop;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.ResponseBody;

import java.util.List;

@Controller
public class MyController {

    @Autowired
    private DbMapper dbMapper;

    @ResponseBody
    @GetMapping("/data")
    public List<MyBean> getPersonList(){
        return dbMapper.getPersonList();
    }
}
複製程式碼

執行程式開啟瀏覽器訪問http://localhost:8080/data後能看到如下輸出:

2018-10-07 10:49:53.811  INFO 19737 --- [nio-8080-exec-1] me.josephzhu.spring101aop.MetricsAspect  : 【入參日誌】呼叫 【class me.josephzhu.spring101aop.MyController】【public java.util.List me.josephzhu.spring101aop.MyController.getPersonList()】【http://localhost:8080/data】 的引數是:【[]】
2018-10-07 10:49:53.819  INFO 19737 --- [nio-8080-exec-1] me.josephzhu.spring101aop.MetricsAspect  : 【成功打點】呼叫 【class me.josephzhu.spring101aop.MyController】【public java.util.List me.josephzhu.spring101aop.MyController.getPersonList()】【http://localhost:8080/data】 成功,耗時:PT-0.008S
2018-10-07 10:49:53.819  INFO 19737 --- [nio-8080-exec-1] me.josephzhu.spring101aop.MetricsAspect  : 【出參日誌】呼叫 【class me.josephzhu.spring101aop.MyController】【public java.util.List me.josephzhu.spring101aop.MyController.getPersonList()】【http://localhost:8080/data】 的返回是:【[MyBean(id=1, name=zhuye, age=35, balance=1000), MyBean(id=2, name=zhuye, age=35, balance=1000)]】
複製程式碼

最後,我們再來踩一個坑。我們來測一下ignoreException吞掉異常的功能(預設為false):

@Transactional(rollbackFor = Exception.class)
@Override
@Metrics(ignoreException = true)
public void insertData(boolean success){
    dbMapper.personInsertWithoutId();
    if(!success)
        dbMapper.personInsertWithId();
}
複製程式碼

這個功能會吞掉異常,在和Transactional事務管理結合時候會不會出問題呢? 開啟這個配置後重新整理頁面可以看到資料庫內有三條記錄了,說明第二次的insertData方法執行沒有成功回滾事務。這也是合情合理的,畢竟我們的MetricsAspect吃掉了異常。

朱曄和你聊Spring系列S1E6:容易犯錯的Spring AOP
怎麼繞開這個問題呢?答案是我們需要手動控制一下我們的切面的執行優先順序,我們希望這個切面優先順序比Spring事務控制切面優先順序低:

@Aspect
@Component
@Slf4j
@Order(1)
public class MetricsAspect {
複製程式碼

再次執行程式可以看到事務正確回滾。

總結

本文我們通過一些例子覆蓋瞭如下內容:

  1. Spring AOP的一些基本知識點。
  2. Mybatis和H2的簡單配置使用。
  3. 如何實現Spring事務管理。
  4. 如何切換為AspjectJ進行AOP。
  5. 觀察JDK代理和CGLIB代理。
  6. 如何定義切面實現事務後處理和日誌異常打點這種橫切關注點。

在整個過程中,也踩了下面的坑,印證的本文的標題:

  1. Spring AOP代理不能作用於代理類內部this方法呼叫的坑。
  2. Spring AOP例項化切面預設單例的坑。
  3. AJC編譯器無法支援lambok的坑。
  4. 切面優先順序順序的坑。
  5. 切面內部獲取註解方式的坑。

老樣子,本系列文章程式碼見我的github:github.com/JosephZhu19…

相關文章