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

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

系統日志：系統日志主要是為開發排查問題提供依據，一般列印在日志檔案中；系統日志的可讀性要求沒那么高，日志中會包含代碼的資訊，比如在某個類的某一行列印了一個日志，

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

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

• 單純的文字記錄，比如：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 運算式包裹起來，這樣做的好處：一是把 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三者之間區別

---------- END ----------

招聘資訊

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

也許你還想看

| Logan Web：前端日志在Web端的實作

| Logan：美團開源移動端基礎日志庫

| Android動態日志系統Holmes

閱讀更多

---

前端 | 演算法 | 后端 | 資料

安全 | Android | iOS | 運維 | 測驗