如何優雅地記錄操作日誌？

操作日誌幾乎存在於每個系統中，而這些系統都有記錄操作日誌的一套 API。操作日誌和系統日誌不一樣，操作日誌必須要做到簡單易懂。所以如何讓操作日誌不跟業務邏輯耦合，如何讓操作日誌的內容易於理解，如何讓操作日誌的接入更加簡單？上面這些都是本文要回答的問題。我們主要圍繞着如何 “優雅” 地記錄操作日誌展開描述，希望對從事相關工作的同學能夠有所幫助或者啓發。

• 1. 操作日誌的使用場景
• 2. 實現方式

• 2.1 使用 Canal 監聽數據庫記錄操作日誌

• 2.2 通過日誌文件的方式記錄

• 2.3 通過 LogUtil 的方式記錄日誌

• 2.4 方法註解實現操作日誌

• 3. 優雅地支持 AOP 生成動態的操作日誌

• 3.1 動態模板

• 4. 代碼實現解析

• 4.1 代碼結構

• 4.2 模塊介紹

• 5. 總結

1. 操作日誌的使用場景

例子

系統日誌和操作日誌的區別

系統日誌：系統日誌主要是爲開發排查問題提供依據，一般打印在日誌文件中；系統日誌的可讀性要求沒那麼高，日誌中會包含代碼的信息，比如在某個類的某一行打印了一個日誌。

操作日誌：主要是對某個對象進行新增操作或者修改操作後記錄下這個新增或者修改，操作日誌要求可讀性比較強，因爲它主要是給用戶看的，比如訂單的物流信息，用戶需要知道在什麼時間發生了什麼事情。再比如，客服對工單的處理記錄信息。

操作日誌的記錄格式大概分爲下面幾種：

• 單純的文字記錄，比如：2021-09-16 10:00 訂單創建。

• 簡單的動態的文本記錄，比如：2021-09-16 10:00 訂單創建，訂單號：NO.11089999，其中涉及變量訂單號 “NO.11089999”。

• 修改類型的文本，包含修改前和修改後的值，比如：2021-09-16 10:00 用戶小明修改了訂單的配送地址：從 “金燦燦小區” 修改到 “銀盞盞小區” ，其中涉及變量配送的原地址“金燦燦小區” 和新地址“銀盞盞小區”。

• 修改表單，一次會修改多個字段。

2. 實現方式

2.1 使用 Canal 監聽數據庫記錄操作日誌

Canal 是一款基於 MySQL 數據庫增量日誌解析，提供增量數據訂閱和消費的開源組件，通過採用監聽數據庫 Binlog 的方式，這樣可以從底層知道是哪些數據做了修改，然後根據更改的數據記錄操作日誌。

這種方式的優點是和業務邏輯完全分離。缺點也很明顯，侷限性太高，只能針對數據庫的更改做操作日誌記錄，如果修改涉及到其他團隊的 RPC 的調用，就沒辦法監聽數據庫了。舉個例子：給用戶發送通知，通知服務一般都是公司內部的公共組件，這時候只能在調用 RPC 的時候手工記錄發送通知的操作日誌了。

2.2 通過日誌文件的方式記錄

log.info("訂單創建")
log.info("訂單已經創建，訂單編號:{}", orderNo)
log.info("修改了訂單的配送地址：從“{}”修改到“{}”， "金燦燦小區", "銀盞盞小區")

這種方式的操作記錄需要解決三個問題。

問題一：操作人如何記錄

藉助 SLF4J 中的 MDC 工具類，把操作人放在日誌中，然後在日誌中統一打印出來。首先在用戶的攔截器中把用戶的標識 Put 到 MDC 中。

@Component
public class UserInterceptor extends HandlerInterceptorAdapter {
  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
    //獲取到用戶標識
    String userNo = getUserNo(request);
    //把用戶 ID 放到 MDC 上下文中
    MDC.put("userId", userNo);
    return super.preHandle(request, response, handler);
  }

  private String getUserNo(HttpServletRequest request) {
    // 通過 SSO 或者Cookie 或者 Auth信息獲取到 當前登陸的用戶信息
    return null;
  }
}

其次，把 userId 格式化到日誌中，使用 %X{userId} 可以取到 MDC 中用戶標識。

<pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern>

問題二：操作日誌如何和系統日誌區分開

通過配置 Log 的配置文件，把有關操作日誌的 Log 單獨放到一日誌文件中。

//不同業務日誌記錄到不同的文件
<appender >
    <File>logs/business.log</File>
    <append>true</append>
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>INFO</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>logs/業務A.%d.%i.log</fileNamePattern>
        <maxHistory>90</maxHistory>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>10MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
    <encoder>
        <pattern>"%d{yyyy-MM-dd HH:mm:ss.SSS} %t %-5level %X{userId} %logger{30}.%method:%L - %msg%n"</pattern>
        <charset>UTF-8</charset>
    </encoder>
</appender>
        
<logger >
    <appender-ref ref="businessLogAppender"/>
</logger>

然後在 Java 代碼中單獨的記錄業務日誌。

//記錄特定日誌的聲明
private final Logger businessLog = LoggerFactory.getLogger("businessLog");
 
//日誌存儲
businessLog.info("修改了配送地址");

問題三：如何生成可讀懂的日誌文案

可以採用 LogUtil 的方式，也可以採用切面的方式生成日誌模板，後續內容將會進行介紹。這樣就可以把日誌單獨保存在一個文件中，然後通過日誌收集可以把日誌保存在 Elasticsearch 或者數據庫中，接下來我們看下如何生成可讀的操作日誌。

2.3 通過 LogUtil 的方式記錄日誌

  LogUtil.log(orderNo, "訂單創建", "小明")
  LogUtil.log(orderNo, "訂單創建，訂單號"+"NO.11089999",  "小明")
  String template = "用戶%s修改了訂單的配送地址：從“%s”修改到“%s”"
  LogUtil.log(orderNo, String.format(tempalte, "小明", "金燦燦小區", "銀盞盞小區"),  "小明")

這裏解釋下爲什麼記錄操作日誌的時候都綁定了一個 OrderNo，因爲操作日誌記錄的是：某一個 “時間”“誰” 對“什麼”做了什麼 “事情”。當查詢業務的操作日誌的時候，會查詢針對這個訂單的的所有操作，所以代碼中加上了 OrderNo，記錄操作日誌的時候需要記錄下操作人，所以傳了操作人“小明” 進來。

上面看起來問題並不大，在修改地址的業務邏輯方法中使用一行代碼記錄了操作日誌，接下來再看一個更復雜的例子：

private OnesIssueDO updateAddress(updateDeliveryRequest request) {
    DeliveryOrder deliveryOrder = deliveryQueryService.queryOldAddress(request.getDeliveryOrderNo());
    // 更新派送信息，電話，收件人，地址
    doUpdate(request);
    String logContent = getLogContent(request, deliveryOrder);
    LogUtils.logRecord(request.getOrderNo(), logContent, request.getOperator);
    return onesIssueDO;
}

private String getLogContent(updateDeliveryRequest request, DeliveryOrder deliveryOrder) {
    String template = "用戶%s修改了訂單的配送地址：從“%s”修改到“%s”";
    return String.format(tempalte, request.getUserName(), deliveryOrder.getAddress(), request.getAddress);
}

可以看到上面的例子使用了兩個方法代碼，外加一個 getLogContent 的函數實現了操作日誌的記錄。當業務變得複雜後，記錄操作日誌放在業務代碼中會導致業務的邏輯比較繁雜，最後導致 LogUtils.logRecord() 方法的調用存在於很多業務的代碼中，而且類似 getLogContent() 這樣的方法也散落在各個業務類中，對於代碼的可讀性和可維護性來說是一個災難。下面介紹下如何避免這個災難。

2.4 方法註解實現操作日誌

爲了解決上面問題，一般採用 AOP 的方式記錄日誌，讓操作日誌和業務邏輯解耦，接下來看一個簡單的 AOP 日誌的例子。

@LogRecord(content="修改了配送地址")
public void modifyAddress(updateDeliveryRequest request){
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

我們可以在註解的操作日誌上記錄固定文案，這樣業務邏輯和業務代碼可以做到解耦，讓我們的業務代碼變得純淨起來。可能有同學注意到，上面的方式雖然解耦了操作日誌的代碼，但是記錄的文案並不符合我們的預期，文案是靜態的，沒有包含動態的文案，因爲我們需要記錄的操作日誌是：用戶 %s 修改了訂單的配送地址，從 “%s” 修改到“%s”。接下來，我們介紹一下如何優雅地使用 AOP 生成動態的操作日誌。

3. 優雅地支持 AOP 生成動態的操作日誌

3.1 動態模板

一提到動態模板，就會涉及到讓變量通過佔位符的方式解析模板，從而達到通過註解記錄操作日誌的目的。模板解析的方式有很多種，這裏使用了 SpEL（Spring Expression Language，Spring 表達式語言）來實現。我們可以先寫下期望的記錄日誌的方式，然後再看看能否實現這樣的功能。

@LogRecord(content = "修改了訂單的配送地址：從“#oldAddress”, 修改到“#request.address”")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

通過 SpEL 表達式引用方法上的參數，可以讓變量填充到模板中達到動態的操作日誌文本內容。但是現在還有幾個問題需要解決：

• 操作日誌需要知道是哪個操作人修改的訂單配送地址。

• 修改訂單配送地址的操作日誌需要綁定在配送的訂單上，從而可以根據配送訂單號查詢出對這個配送訂單的所有操作。

• 爲了在註解上記錄之前的配送地址是什麼，在方法簽名上添加了一個和業務無關的 oldAddress 的變量，這樣就不優雅了。

爲了解決前兩個問題，我們需要把期望的操作日誌使用形式改成下面的方式：

@LogRecord(
     content = "修改了訂單的配送地址：從“#oldAddress”, 修改到“#request.address”",
     operator = "#request.userName", bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

修改後的代碼在註解上添加兩個參數，一個是操作人，一個是操作日誌需要綁定的對象。但是，在普通的 Web 應用中用戶信息都是保存在一個線程上下文的靜態方法中，所以 operator 一般是這樣的寫法（假定獲取當前登陸用戶的方式是 UserContext.getCurrentUser()）。

operator = "#{T(com.meituan.user.UserContext).getCurrentUser()}"

這樣的話，每個 @LogRecord 的註解上的操作人都是這麼長一串。爲了避免過多的重複代碼，我們可以把註解上的 operator 參數設置爲非必填，這樣用戶可以填寫操作人。但是，如果用戶不填寫我們就取 UserContext 的 user（下文會介紹如何取 user）。最後，最簡單的日誌變成了下面的形式：

@LogRecord(content = "修改了訂單的配送地址：從“#oldAddress”, 修改到“#request.address”", 
           bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request, String oldAddress){
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

接下來，我們需要解決第三個問題：爲了記錄業務操作記錄添加了一個 oldAddress 變量，不管怎麼樣這都不是一個好的實現方式，所以接下來，我們需要把 oldAddress 變量從修改地址的方法簽名上去掉。但是操作日誌確實需要 oldAddress 變量，怎麼辦呢？

要麼和產品經理 PK 一下，讓產品經理把文案從 “修改了訂單的配送地址：從 xx 修改到 yy” 改爲 “修改了訂單的配送地址爲：yy”。但是從用戶體驗上來看，第一種文案更人性化一些，顯然我們不會 PK 成功的。那麼我們就必須要把這個 oldAddress 查詢出來然後供操作日誌使用了。還有一種解決辦法是：把這個參數放到操作日誌的線程上下文中，供註解上的模板使用。我們按照這個思路再改下操作日誌的實現代碼。

@LogRecord(content = "修改了訂單的配送地址：從“#oldAddress”, 修改到“#request.address”",
        bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
    // 查詢出原來的地址是什麼
    LogRecordContext.putVariable("oldAddress", DeliveryService.queryOldAddress(request.getDeliveryOrderNo()));
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

這時候可以看到，LogRecordContext 解決了操作日誌模板上使用方法參數以外變量的問題，同時避免了爲了記錄操作日誌修改方法簽名的設計。雖然已經比之前的代碼好了些，但是依然需要在業務代碼裏面加了一行業務邏輯無關的代碼，如果有 “強迫症” 的同學還可以繼續往下看，接下來我們會講解自定義函數的解決方案。下面再看另一個例子：

@LogRecord(content = "修改了訂單的配送員：從“#oldDeliveryUserId”, 修改到“#request.userId”",
        bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
    // 查詢出原來的地址是什麼
    LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

這個操作日誌的模板最後記錄的內容是這樣的格式：修改了訂單的配送員：從 “10090”，修改到 “10099”，顯然用戶看到這樣的操作日誌是不明白的。用戶對於用戶 ID 是 10090 還是 10099 並不瞭解，用戶期望看到的是：修改了訂單的配送員：從 “張三（18910008888）”，修改到 “小明（13910006666）”。用戶關心的是配送員的姓名和電話。但是我們方法中傳遞的參數只有配送員的 ID，沒有配送員的姓名可電話。我們可以通過上面的方法，把用戶的姓名和電話查詢出來，然後通過 LogRecordContext 實現。

但是，“強迫症” 是不期望操作日誌的代碼嵌入在業務邏輯中的。接下來，我們考慮另一種實現方式：自定義函數。如果我們可以通過自定義函數把用戶 ID 轉換爲用戶姓名和電話，那麼就能解決這一問題，按照這個思路，我們把模板修改爲下面的形式：

@LogRecord(content = "修改了訂單的配送員：從“{deliveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.userId}}”",
        bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
    // 查詢出原來的地址是什麼
    LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

其中 deliveryUser 是自定義函數，使用大括號把 Spring 的 SpEL 表達式包裹起來，這樣做的好處：一是把 Spring EL 表達式和自定義函數區分開便於解析；二是如果模板中不需要 SpEL 表達式解析可以容易的識別出來，減少 SpEL 的解析提高性能。這時候我們發現上面代碼還可以優化成下面的形式：

@LogRecord(content = "修改了訂單的配送員：從“{queryOldUser{#request.deliveryOrderNo()}}”, 修改到“{deveryUser{#request.userId}}”",
        bizNo="#request.deliveryOrderNo")
public void modifyAddress(updateDeliveryRequest request){
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

這樣就不需要在 modifyAddress 方法中通過 LogRecordContext.putVariable() 設置老的快遞員了，通過直接新加一個自定義函數 queryOldUser() 參數把派送訂單傳遞進去，就能查到之前的配送人了，只需要讓方法的解析在 modifyAddress() 方法執行之前運行。這樣的話，我們讓業務代碼又變得純淨了起來，同時也讓 “強迫症” 不再感到難受了。

4. 代碼實現解析

4.1 代碼結構

上面的操作日誌主要是通過一個 AOP 攔截器實現的，整體主要分爲 AOP 模塊、日誌解析模塊、日誌保存模塊、Starter 模塊；組件提供了 4 個擴展點，分別是：自定義函數、默認處理人、業務保存和查詢；業務可以根據自己的業務特性定製符合自己業務的邏輯。

4.2 模塊介紹

有了上面的分析，已經得出一種我們期望的操作日誌記錄的方式，接下來我們看下如何實現上面的邏輯。實現主要分爲下面幾個步驟：

• AOP 攔截邏輯

• 解析邏輯

• 模板解析

• LogContext 邏輯

• 默認的 operator 邏輯

• 自定義函數邏輯

• 默認的日誌持久化邏輯

• Starter 封裝邏輯

4.2.1 AOP 攔截邏輯

這塊邏輯主要是一個攔截器，針對 @LogRecord 註解分析出需要記錄的操作日誌，然後把操作日誌持久化，這裏把註解命名爲 @LogRecordAnnotation。接下來，我們看下註解的定義：

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Inherited
@Documented
public @interface LogRecordAnnotation {
    String success();

    String fail() default "";

    String operator() default "";

    String bizNo();

    String category() default "";

    String detail() default "";

    String condition() default "";
}

註解中除了上面提到參數外，還增加了 fail、category、detail、condition 等參數，這幾個參數是爲了滿足特定的場景，後面還會給出具體的例子。

爲了保持簡單，組件的必填參數就兩個。業務中的 AOP 邏輯大部分是使用 @Aspect 註解實現的，但是基於註解的 AOP 在 Spring boot 1.5 中兼容性是有問題的，組件爲了兼容 Spring boot1.5 的版本我們手工實現 Spring 的 AOP 邏輯。

切面選擇 AbstractBeanFactoryPointcutAdvisor 實現，切點是通過 StaticMethodMatcherPointcut 匹配包含 LogRecordAnnotation 註解的方法。通過實現 MethodInterceptor接口實現操作日誌的增強邏輯。

下面是攔截器的切點邏輯：

public class LogRecordPointcut extends StaticMethodMatcherPointcut implements Serializable {
    // LogRecord的解析類
    private LogRecordOperationSource logRecordOperationSource;
    
    @Override
    public boolean matches(@NonNull Method method, @NonNull Class<?> targetClass) {
          // 解析 這個 method 上有沒有 @LogRecordAnnotation 註解，有的話會解析出來註解上的各個參數
        return !CollectionUtils.isEmpty(logRecordOperationSource.computeLogRecordOperations(method, targetClass));
    }

    void setLogRecordOperationSource(LogRecordOperationSource logRecordOperationSource) {
        this.logRecordOperationSource = logRecordOperationSource;
    }
}

切面的增強邏輯主要代碼如下：

@Override
public Object invoke(MethodInvocation invocation) throws Throwable {
    Method method = invocation.getMethod();
    // 記錄日誌
    return execute(invocation, invocation.getThis(), method, invocation.getArguments());
}

private Object execute(MethodInvocation invoker, Object target, Method method, Object[] args) throws Throwable {
    Class<?> targetClass = getTargetClass(target);
    Object ret = null;
    MethodExecuteResult methodExecuteResult = new MethodExecuteResult(true, null, "");
    LogRecordContext.putEmptySpan();
    Collection<LogRecordOps> operations = new ArrayList<>();
    Map<String, String> functionNameAndReturnMap = new HashMap<>();
    try {
        operations = logRecordOperationSource.computeLogRecordOperations(method, targetClass);
        List<String> spElTemplates = getBeforeExecuteFunctionTemplate(operations);
        //業務邏輯執行前的自定義函數解析
        functionNameAndReturnMap = processBeforeExecuteFunctionTemplate(spElTemplates, targetClass, method, args);
    } catch (Exception e) {
        log.error("log record parse before function exception", e);
    }
    try {
        ret = invoker.proceed();
    } catch (Exception e) {
        methodExecuteResult = new MethodExecuteResult(false, e, e.getMessage());
    }
    try {
        if (!CollectionUtils.isEmpty(operations)) {
            recordExecute(ret, method, args, operations, targetClass,
                    methodExecuteResult.isSuccess(), methodExecuteResult.getErrorMsg(), functionNameAndReturnMap);
        }
    } catch (Exception t) {
        //記錄日誌錯誤不要影響業務
        log.error("log record parse exception", t);
    } finally {
        LogRecordContext.clear();
    }
    if (methodExecuteResult.throwable != null) {
        throw methodExecuteResult.throwable;
    }
    return ret;
}

攔截邏輯的流程：

可以看到，操作日誌的記錄持久化是在方法執行完之後執行的，當方法拋出異常之後會先捕獲異常，等操作日誌持久化完成後再拋出異常。在業務的方法執行之前，會對提前解析的自定義函數求值，解決了前面提到的需要查詢修改之前的內容。

4.2.2 解析邏輯

模板解析

Spring 3 中提供了一個非常強大的功能：SpEL，SpEL 在 Spring 產品中是作爲表達式求值的核心基礎模塊，它本身是可以脫離 Spring 獨立使用的。舉個例子：

public static void main(String[] args) {
        SpelExpressionParser parser = new SpelExpressionParser();
        Expression expression = parser.parseExpression("#root.purchaseName");
        Order order = new Order();
        order.setPurchaseName("張三");
        System.out.println(expression.getValue(order));
}

這個方法將打印 “張三”。LogRecord 解析的類圖如下：

解析核心類：LogRecordValueParser 裏面封裝了自定義函數和 SpEL 解析類 LogRecordExpressionEvaluator。

public class LogRecordExpressionEvaluator extends CachedExpressionEvaluator {

    private Map<ExpressionKey, Expression> expressionCache = new ConcurrentHashMap<>(64);

    private final Map<AnnotatedElementKey, Method> targetMethodCache = new ConcurrentHashMap<>(64);

    public String parseExpression(String conditionExpression, AnnotatedElementKey methodKey, EvaluationContext evalContext) {
        return getExpression(this.expressionCache, methodKey, conditionExpression).getValue(evalContext, String.class);
    }
}

LogRecordExpressionEvaluator 繼承自 CachedExpressionEvaluator 類，這個類裏面有兩個 Map，一個是 expressionCache 一個是 targetMethodCache。在上面的例子中可以看到，SpEL 會解析成一個 Expression 表達式，然後根據傳入的 Object 獲取到對應的值，所以 expressionCache 是爲了緩存方法、表達式和 SpEL 的 Expression 的對應關係，讓方法註解上添加的 SpEL 表達式只解析一次。下面的 targetMethodCache 是爲了緩存傳入到 Expression 表達式的 Object。核心的解析邏輯是上面最後一行代碼。

getExpression(this.expressionCache, methodKey, conditionExpression).getValue(evalContext, String.class);

getExpression 方法會從 expressionCache 中獲取到 @LogRecordAnnotation 註解上的表達式的解析 Expression 的實例，然後調用 getValue 方法，getValue 傳入一個 evalContext 就是類似上面例子中的 order 對象。其中 Context 的實現將會在下文介紹。

日誌上下文實現

下面的例子把變量放到了 LogRecordContext 中，然後 SpEL 表達式就可以順利的解析方法上不存在的參數了，通過上面的 SpEL 的例子可以看出，要把方法的參數和 LogRecordContext 中的變量都放到 SpEL 的 getValue 方法的 Object 中才可以順利的解析表達式的值。下面看看如何實現：

@LogRecord(content = "修改了訂單的配送員：從“{deveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.getUserId()}}”",
            bizNo="#request.getDeliveryOrderNo()")
public void modifyAddress(updateDeliveryRequest request){
    // 查詢出原來的地址是什麼
    LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

在 LogRecordValueParser 中創建了一個 EvaluationContext，用來給 SpEL 解析方法參數和 Context 中的變量。相關代碼如下：

EvaluationContext evaluationContext = expressionEvaluator.createEvaluationContext(method, args, targetClass, ret, errorMsg, beanFactory);

在解析的時候調用 getValue 方法傳入的參數 evalContext，就是上面這個 EvaluationContext 對象。下面是 LogRecordEvaluationContext 對象的繼承體系：

LogRecordEvaluationContext 做了三個事情：

• 把方法的參數都放到 SpEL 解析的 RootObject 中。

• 把 LogRecordContext 中的變量都放到 RootObject 中。

• 把方法的返回值和 ErrorMsg 都放到 RootObject 中。

LogRecordEvaluationContext 的代碼如下：

public class LogRecordEvaluationContext extends MethodBasedEvaluationContext {

    public LogRecordEvaluationContext(Object rootObject, Method method, Object[] arguments,
                                      ParameterNameDiscoverer parameterNameDiscoverer, Object ret, String errorMsg) {
       //把方法的參數都放到 SpEL 解析的 RootObject 中
       super(rootObject, method, arguments, parameterNameDiscoverer);
       //把 LogRecordContext 中的變量都放到 RootObject 中
        Map<String, Object> variables = LogRecordContext.getVariables();
        if (variables != null && variables.size() > 0) {
            for (Map.Entry<String, Object> entry : variables.entrySet()) {
                setVariable(entry.getKey(), entry.getValue());
            }
        }
        //把方法的返回值和 ErrorMsg 都放到 RootObject 中
        setVariable("_ret", ret);
        setVariable("_errorMsg", errorMsg);
    }
}

下面是 LogRecordContext 的實現，這個類裏面通過一個 ThreadLocal 變量保持了一個棧，棧裏面是個 Map，Map 對應了變量的名稱和變量的值。

public class LogRecordContext {

    private static final InheritableThreadLocal<Stack<Map<String, Object>>> variableMapStack = new InheritableThreadLocal<>();
   //其他省略....
}

上面使用了 InheritableThreadLocal，所以在線程池的場景下使用 LogRecordContext 會出現問題，如果支持線程池可以使用阿里巴巴開源的 TTL 框架。那這裏爲什麼不直接設置一個 ThreadLocal<Map<String, Object>> 對象，而是要設置一個 Stack 結構呢？我們看一下這麼做的原因是什麼。

@LogRecord(content = "修改了訂單的配送員：從“{deveryUser{#oldDeliveryUserId}}”, 修改到“{deveryUser{#request.getUserId()}}”",
        bizNo="#request.getDeliveryOrderNo()")
public void modifyAddress(updateDeliveryRequest request){
    // 查詢出原來的地址是什麼
    LogRecordContext.putVariable("oldDeliveryUserId", DeliveryService.queryOldDeliveryUserId(request.getDeliveryOrderNo()));
    // 更新派送信息 電話，收件人、地址
    doUpdate(request);
}

上面代碼的執行流程如下：

看起來沒有什麼問題，但是使用 LogRecordAnnotation 的方法裏面嵌套了另一個使用 LogRecordAnnotation 方法的時候，流程就變成下面的形式：

可以看到，當方法二執行了釋放變量後，繼續執行方法一的 logRecord 邏輯，此時解析的時候 ThreadLocal<Map<String, Object>> 的 Map 已經被釋放掉，所以方法一就獲取不到對應的變量了。方法一和方法二共用一個變量 Map 還有個問題是：如果方法二設置了和方法一相同的變量兩個方法的變量就會被相互覆蓋。所以最終 LogRecordContext 的變量的生命週期需要是下面的形式：

LogRecordContext 每執行一個方法都會壓棧一個 Map，方法執行完之後會 Pop 掉這個 Map，從而避免變量共享和覆蓋問題。

默認操作人邏輯

在 LogRecordInterceptor 中 IOperatorGetService 接口，這個接口可以獲取到當前的用戶。下面是接口的定義：

public interface IOperatorGetService {

    /**
     * 可以在裏面外部的獲取當前登陸的用戶，比如 UserContext.getCurrentUser()
     *
     * @return 轉換成Operator返回
     */
    Operator getUser();
}

下面給出了從用戶上下文中獲取用戶的例子：

public class DefaultOperatorGetServiceImpl implements IOperatorGetService {

    @Override
    public Operator getUser() {
    //UserUtils 是獲取用戶上下文的方法
         return Optional.ofNullable(UserUtils.getUser())
                        .map(a -> new Operator(a.getName(), a.getLogin()))
                        .orElseThrow(()->new IllegalArgumentException("user is null"));
        
    }
}

組件在解析 operator 的時候，就判斷註解上的 operator 是否是空，如果註解上沒有指定，我們就從 IOperatorGetService 的 getUser 方法獲取了。如果都獲取不到，就會報錯。

String realOperatorId = "";
if (StringUtils.isEmpty(operatorId)) {
    if (operatorGetService.getUser() == null || StringUtils.isEmpty(operatorGetService.getUser().getOperatorId())) {
        throw new IllegalArgumentException("user is null");
    }
    realOperatorId = operatorGetService.getUser().getOperatorId();
} else {
    spElTemplates = Lists.newArrayList(bizKey, bizNo, action, operatorId, detail);
}

自定義函數邏輯

自定義函數的類圖如下：

下面是 IParseFunction 的接口定義：executeBefore 函數代表了自定義函數是否在業務代碼執行之前解析，上面提到的查詢修改之前的內容。

public interface IParseFunction {

  default boolean executeBefore(){
    return false;
  }

  String functionName();

  String apply(String value);
}

ParseFunctionFactory 的代碼比較簡單，它的功能是把所有的 IParseFunction 注入到函數工廠中。

public class ParseFunctionFactory {
  private Map<String, IParseFunction> allFunctionMap;

  public ParseFunctionFactory(List<IParseFunction> parseFunctions) {
    if (CollectionUtils.isEmpty(parseFunctions)) {
      return;
    }
    allFunctionMap = new HashMap<>();
    for (IParseFunction parseFunction : parseFunctions) {
      if (StringUtils.isEmpty(parseFunction.functionName())) {
        continue;
      }
      allFunctionMap.put(parseFunction.functionName(), parseFunction);
    }
  }

  public IParseFunction getFunction(String functionName) {
    return allFunctionMap.get(functionName);
  }

  public boolean isBeforeFunction(String functionName) {
    return allFunctionMap.get(functionName) != null && allFunctionMap.get(functionName).executeBefore();
  }
}

DefaultFunctionServiceImpl 的邏輯就是根據傳入的函數名稱 functionName 找到對應的 IParseFunction，然後把參數傳入到 IParseFunction 的 apply 方法上最後返回函數的值。

public class DefaultFunctionServiceImpl implements IFunctionService {

  private final ParseFunctionFactory parseFunctionFactory;

  public DefaultFunctionServiceImpl(ParseFunctionFactory parseFunctionFactory) {
    this.parseFunctionFactory = parseFunctionFactory;
  }

  @Override
  public String apply(String functionName, String value) {
    IParseFunction function = parseFunctionFactory.getFunction(functionName);
    if (function == null) {
      return value;
    }
    return function.apply(value);
  }

  @Override
  public boolean beforeFunction(String functionName) {
    return parseFunctionFactory.isBeforeFunction(functionName);
  }
}

4.2.3 日誌持久化邏輯

同樣在 LogRecordInterceptor 的代碼中引用了 ILogRecordService，這個 Service 主要包含了日誌記錄的接口。

public interface ILogRecordService {
    /**
     * 保存 log
     *
     * @param logRecord 日誌實體
     */
    void record(LogRecord logRecord);

}

業務可以實現這個保存接口，然後把日誌保存在任何存儲介質上。這裏給了一個 2.2 節介紹的通過 log.info 保存在日誌文件中的例子，業務可以把保存設置成異步或者同步，可以和業務放在一個事務中保證操作日誌和業務的一致性，也可以新開闢一個事務，保證日誌的錯誤不影響業務的事務。業務可以保存在 Elasticsearch、數據庫或者文件中，用戶可以根據日誌結構和日誌的存儲實現相應的查詢邏輯。

@Slf4j
public class DefaultLogRecordServiceImpl implements ILogRecordService {

    @Override
//    @Transactional(propagation = Propagation.REQUIRES_NEW)
    public void record(LogRecord logRecord) {
        log.info("【logRecord】log={}", logRecord);
    }
}

4.2.4 Starter 邏輯封裝

上面邏輯代碼已經介紹完畢，那麼接下來需要把這些組件組裝起來，然後讓用戶去使用。在使用這個組件的時候只需要在 Springboot 的入口上添加一個註解 @EnableLogRecord(tenant = "com.mzt.test")。其中 tenant 代表租戶，是爲了多租戶使用的。

@SpringBootApplication(exclude = DataSourceAutoConfiguration.class)
@EnableTransactionManagement
@EnableLogRecord(tenant = "com.mzt.test")
public class Main {

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

我們再看下 EnableLogRecord 的代碼，代碼中 Import 了 LogRecordConfigureSelector.class，在 LogRecordConfigureSelector 類中暴露了 LogRecordProxyAutoConfiguration 類。

@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Import(LogRecordConfigureSelector.class)
public @interface EnableLogRecord {

    String tenant();
    
    AdviceMode mode() default AdviceMode.PROXY;
}

LogRecordProxyAutoConfiguration 就是裝配上面組件的核心類了，代碼如下：

@Configuration
@Slf4j
public class LogRecordProxyAutoConfiguration implements ImportAware {

  private AnnotationAttributes enableLogRecord;


  @Bean
  @Role(BeanDefinition.ROLE_INFRASTRUCTURE)
  public LogRecordOperationSource logRecordOperationSource() {
    return new LogRecordOperationSource();
  }

  @Bean
  @ConditionalOnMissingBean(IFunctionService.class)
  public IFunctionService functionService(ParseFunctionFactory parseFunctionFactory) {
    return new DefaultFunctionServiceImpl(parseFunctionFactory);
  }

  @Bean
  public ParseFunctionFactory parseFunctionFactory(@Autowired List<IParseFunction> parseFunctions) {
    return new ParseFunctionFactory(parseFunctions);
  }

  @Bean
  @ConditionalOnMissingBean(IParseFunction.class)
  public DefaultParseFunction parseFunction() {
    return new DefaultParseFunction();
  }


  @Bean
  @Role(BeanDefinition.ROLE_INFRASTRUCTURE)
  public BeanFactoryLogRecordAdvisor logRecordAdvisor(IFunctionService functionService) {
    BeanFactoryLogRecordAdvisor advisor =
            new BeanFactoryLogRecordAdvisor();
    advisor.setLogRecordOperationSource(logRecordOperationSource());
    advisor.setAdvice(logRecordInterceptor(functionService));
    return advisor;
  }

  @Bean
  @Role(BeanDefinition.ROLE_INFRASTRUCTURE)
  public LogRecordInterceptor logRecordInterceptor(IFunctionService functionService) {
    LogRecordInterceptor interceptor = new LogRecordInterceptor();
    interceptor.setLogRecordOperationSource(logRecordOperationSource());
    interceptor.setTenant(enableLogRecord.getString("tenant"));
    interceptor.setFunctionService(functionService);
    return interceptor;
  }

  @Bean
  @ConditionalOnMissingBean(IOperatorGetService.class)
  @Role(BeanDefinition.ROLE_APPLICATION)
  public IOperatorGetService operatorGetService() {
    return new DefaultOperatorGetServiceImpl();
  }

  @Bean
  @ConditionalOnMissingBean(ILogRecordService.class)
  @Role(BeanDefinition.ROLE_APPLICATION)
  public ILogRecordService recordService() {
    return new DefaultLogRecordServiceImpl();
  }

  @Override
  public void setImportMetadata(AnnotationMetadata importMetadata) {
    this.enableLogRecord = AnnotationAttributes.fromMap(
            importMetadata.getAnnotationAttributes(EnableLogRecord.class.getName(), false));
    if (this.enableLogRecord == null) {
      log.info("@EnableCaching is not present on importing class");
    }
  }
}

這個類繼承 ImportAware 是爲了拿到 EnableLogRecord 上的租戶屬性，這個類使用變量 logRecordAdvisor 和 logRecordInterceptor 裝配了 AOP，同時把自定義函數注入到了 logRecordAdvisor 中。

對外擴展類：分別是IOperatorGetService、ILogRecordService、IParseFunction。業務可以自己實現相應的接口，因爲配置了 @ConditionalOnMissingBean，所以用戶的實現類會覆蓋組件內的默認實現。

5. 總結

這篇文章介紹了操作日誌的常見寫法，以及如何讓操作日誌的實現更加簡單、易懂，通過組件的四個模塊，介紹了組件的具體實現。對於上面的組件介紹，大家如果有疑問，也歡迎在文末留言，我們會進行答疑。

6. 作者簡介

站通，2020 年加入美團，基礎研發平臺 / 研發質量及效率部工程師。

7. 參考資料

• Canal

• Spring-Framework

• Spring Expression Language (SpEL)

• ThreadLocal、InheritableThreadLocal、TransmittableThreadLocal 三者之間區別

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/eBEdRegvofnDqsJWfuw7yw