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

美團技術團隊發表於2021-09-18
操作日誌廣泛存在於各個B端和一些C端系統中，比如：客服可以根據工單的操作日誌快速知道哪些人對這個工單做了哪些操作，進而快速地定位問題。操作日誌和系統日誌不一樣，操作日誌必須要做到簡單易懂。所以如何讓操作日誌不和業務邏輯耦合，如何讓操作日誌的內容易於理解，讓操作日誌的接入更加簡單？上面這些都是本文要回答的問題，主要圍繞著如何“優雅”地記錄操作日誌展開描述。

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 name="businessLogAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <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 name="businessLog" additivity="false" level="INFO">
    <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 表示式包裹起來，這樣做的好處：一是把 SpEL（Spring Expression Language，Spring表示式語言）和自定義函式區分開便於解析；二是如果模板中不需要 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 等引數，這幾個引數是為了滿足特定的場景，後面還會給出具體的例子。

引數名描述是否必填
success操作日誌的文字模板是
fail操作日誌失敗的文字版本否
operator操作日誌的執行人否
bizNo操作日誌繫結的業務物件標識是
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 提供了一個非常強大的功能：Spring EL，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. 參考資料

8. 招聘資訊

美團研發質量及效率部 ，致力於建設業界一流的持續交付平臺，現招聘基礎元件方向相關的工程師，座標北京/上海。歡迎感興趣的同學加入。可投遞簡歷至：chao.yu@meituan.com（郵件主題請註明：美團研發質量及效率部）。

閱讀美團技術團隊更多技術文章合集

前端 | 演算法 | 後端 | 資料 | 安全 | 運維 | iOS | Android | 測試

| 在公眾號選單欄對話方塊回覆【2020年貨】、【2019年貨】、【2018年貨】、【2017年貨】等關鍵詞，可檢視美團技術團隊歷年技術文章合集。

| 本文系美團技術團隊出品，著作權歸屬美團。歡迎出於分享和交流等非商業目的轉載或使用本文內容，敬請註明“內容轉載自美團技術團隊”。本文未經許可，不得進行商業性轉載或者使用。任何商用行為，請傳送郵件至tech@meituan.com申請授權。

相關文章