优雅地实现操作日志记录

参考文章：https://tech.meituan.com/2021/09/16/operational-logbook.html

背景

最近看到了美团的这篇文章，想起以前学习切面编程时，实现过简单的接口操作日志记录注解，能记录单据类型、操作人、操作时间、操作描述、请求参数等，但是主要的日志数据都是固定写死到注解里面的，那如果有更灵活一些的需求呢？譬如：

• 记录业务唯一标识，即业务单号，需根据每次请求动态获取；
• 操作描述支持动态参数填入，支持动态函数的执行和替换；
• 针对比较多字段编辑的场景，需记录更新前的原始数据。

于是重新实现了一版操作日志注解。至于日志记录的必要性以及简单实现等就不过多赘述，这里重点说一下对于以上几个需求的实现。

流程

动态函数注册

日志切面解析

实现

1. 自定义注解

先看看日志注解：

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface DataLog {
    /**
     * 单笔数据操作时可指定，SpEL.
     */
    String billId() default "";
    /**
     * 单据类型，所属的业务模块，一般指定为固定值.
     */
    String billType();

    /**
     * 操作描述，支持SpEL模板，支持自定义函数.
     */
    String operationDesc();

    /**
     * 查询更新操作的原始数据时自定义函数名称，根据billId查询.
     */
    String originalDataFunction() default "";

    /**
     * 自定义函数执行时可选的分表字段值，SpEL.
     */
    String shardingId() default "";
}

注解里面需要用到SpEL，对于动态获取参数字段值，首选的当然是SpEL表达式语言，简单强大。这里面billId、operationDesc、shardingId都需要从参数中动态取值的，而接口的参数会有两种情况，一种是多个参数，一种是整个对象作为请求body的单个参数。

注解使用示例如下：

// 多个参数值
@GetMapping(value = "/query")
@DataLog(billId = "#{#id}",
         shardingId = "#{#id}",
         billType = "test",
         operationDesc = "id为#{#id}. id2为#{#id2}",
         originalDataFunction = "prefix")
public ResultVO<String> query(@RequestParam("id") String id, @RequestParam("id2") String id2) {
    return ResultUtils.success("success");
}

// 单个对象请求
@PostMapping(value = "/post")
@DataLog(billId = "#{id}",
         shardingId = "#{id}",
         billType = "test",
         operationDesc = "id是#{id!=null?id:'默认值'}")
public ResultVO<String> post(@RequestBody TestDTO dto) {
    return ResultUtils.success("success");
}

针对多参数的情况，取值的写法看起来有些奇怪，这是因为同时使用了SpEL的 StandardEvaluationContext和TemplateParserContext，这样做也是为了能兼容操作描述中的模板表达式的写法。

2. SpEL实现动态参数获取

核心代码如下：

private static final ExpressionParser PARSER = new SpelExpressionParser();
private static final LocalVariableTableParameterNameDiscoverer DISCOVERER = new LocalVariableTableParameterNameDiscoverer();
private static final ThreadLocal<StandardEvaluationContext> CONTEXT_THREAD_LOCAL = new ThreadLocal<>();

public static String templateParse(String text, Method method, Object[] argsObj) {
    String[] parameterNames = DISCOVERER.getParameterNames(method);
    if (parameterNames == null) {
        return text;
    }
    // 由于存在业务操作执行前后都要进行解析的场景，所以使用ThreadLocal存储上下文的context，避免重复创建
    StandardEvaluationContext context = CONTEXT_THREAD_LOCAL.get();
    if (context != null) {
        return PARSER.parseExpression(text, new TemplateParserContext()).getValue(context, String.class);
    }
    context = new StandardEvaluationContext();
    // 把接口的所有参数都放到context中
    for (int i = 0; i < parameterNames.length; i++) {
        context.setVariable(parameterNames[i], argsObj[i]);
    }
    // 获取对象中的属性值时，使用第一个参数作为rootObject
    context.setRootObject(argsObj[0]);
    CONTEXT_THREAD_LOCAL.set(context);
    // 结合使用`模板`和`标准`的表达式解析
    return PARSER.parseExpression(text, new TemplateParserContext()).getValue(context, String.class);
}

public static void removeContext() {
    CONTEXT_THREAD_LOCAL.remove();
}

3. 动态函数的执行和替换

注解使用的方式：

@PostMapping(value = "/post2")
@DataLog(billId = "#{id}",
         shardingId = "#{id}",
         billType = "test",
         operationDesc = "id是#{id!=null?id:'默认值'}，自定义动态函数@customeFunction(#{id},#{name})")
public ResultVO<String> post2(@RequestBody TestDTO dto) {
    List<SnEntity> snEntities = snTestMapper.selectList(Wrappers.lambdaQuery(SnEntity.class));
    return ResultUtils.success(snEntities.get(0).getPeriodName());
}

动态函数的使用主要是在 操作描述(operationDesc) 中，由于某些场景下需要填充一些动态查询的数据到描述中去，故需要支持。这个地方按照原文的思路来做是可以使用MethodBasedEvaluationContext来实现，而StandardEvaluationContext是MethodBasedEvaluationContext的父类，所以也可以使用StandardEvaluationContext#registerFunction函数来进行注册。但这需要获取目标类的Method信息作为参数，感觉比较麻烦，所以我并没有使用这种方法，而是自定义了函数式接口进行注册，先看看自定义函数以及注册的方式：

// 函数式接口，便于实现自定义的逻辑
@FunctionalInterface
public interface IFunction<R> {
    // 动态入参（这里的设计或许不够好）
    R apply(String... params);
}

public class LogParseFunctionFactory {

    public static final Map<String, IFunction<Object>> FUNCTION_MAP = new HashMap<>(32);

    /**
     * 操作日志自定义函数注册.
     *
     * @param functionName 函数名称
     * @param function     函数体
     */
    public static void registerFunction(String functionName, IFunction<Object> function) {
        if (!FUNCTION_MAP.containsKey(functionName)) {
            FUNCTION_MAP.put(functionName, function);
        }
    }
}

// 实现与注册逻辑
@Component
public class ServiceRegistry {

    @Resource
    private BizMapper bizMapper;
    
    @PostConstruct
    void initRegistry() {
        // 注册自定义函数，customeFunction对应描述中的函数名称
        LogParseFunctionFactory.registerFunction("customeFunction", (params) -> {
            return bizMapper.query(params[0]);
        });
    }
}

解析函数名称、执行函数并进行结果替换：

// 约定函数声明的格式，形如 @functionName(param0,param1)，其中的param可以通过SpEL进行注入，也可以固定
private static final char AT = '@';
private static final char LEFT_BRACKET = '(';
private static final char RIGHT_BRACKET = ')';
private static final String WHITESPACE = " ";
private static final String EMPTY = "";
private static final String COMMA = ",";

public static String functionParse(String text) {
    char[] chars = text.toCharArray();
    // 由于需要对占位的函数进行结果替换，需要新字符串，预先扩展一部分空间，避免循环中不必要的扩容操作。空间换时间
    StringBuilder builder = new StringBuilder(text.length() + (text.length() / 2));
    int offset = 0;
    for (int i = 0; i < chars.length; i++) {
        char ch = chars[i];
        if (AT != ch) {
            continue;
        }
        // 解析自定义函数
        int j = i + 1;
        while (j < chars.length && chars[j] != LEFT_BRACKET) {
            j++;
        }
        String funcName = doParse(chars, j, i);
        // 解析函数参数
        int l = j;
        while (j < chars.length && chars[j] != RIGHT_BRACKET) {
            j++;
        }
        String params = doParse(chars, j, l);
        IFunction<Object> function = LogParseFunctionFactory.FUNCTION_MAP.get(funcName.trim());
        if (function == null) {
            continue;
        }
        // 替换空白，使用apache lang包的replace方法，性能更佳
        String actualParams = StringUtils.replace(params, WHITESPACE, EMPTY);
        // 执行动态函数
        Object funcResult = function.apply(actualParams.split(COMMA));
        // 替换动态函数为执行的结果
        String replacement = (funcResult == null ? "" : funcResult.toString());
        builder.append(text, offset, i).append(replacement);
        offset = j + 1;
    }
    builder.append(text, offset, text.length());
    return builder.toString();
}

private static String doParse(char[] chars, int x, int y) {
    byte[] bytes = new byte[x - 1 - y];
    for (int k = 0; k < (x - 1 - y); k++) {
        bytes[k] = (byte) chars[y + 1 + k];
    }
    return new String(bytes);
}

4. 更新前原始数据的获取

这里要用到的是注解里面的originalDataFunction字段，函数的注册方式同上，只是在调用的地方不太一样，是在操作执行前调用的。

// 使用示例
@PostMapping(value = "/post")
@DataLog(billId = "#{id}",
         shardingId = "#{id}",
         billType = "test",
         originalDataFunction = "originalFunction")
public ResultVO<String> post(@RequestBody TestDTO dto) {
    return ResultUtils.success("success");
}

解析执行逻辑：

// 注解获取等
...
String originalData = null;
// 判断是否指定了自定义函数且单号必须指定
if (StrUtil.isNotBlank(logHandler.originalDataFunction) && StrUtil.isNotBlank(logHandler.billId)) {
    try {
        String finalBillId = ExpressionHandler.templateParse(logHandler.billId, logHandler.method, argsObj);
        String shardingId = ExpressionHandler.templateParse(logHandler.shardingId, logHandler.method, argsObj);
        // 自定义函数查询原始数据，也是用的上面的函数注册方法
        IFunction<Object> function = LogParseFunctionFactory.FUNCTION_MAP.get(logHandler.originalDataFunction);
        Object originalDataObject = Optional.ofNullable(function)
            .map(f -> f.apply(finalBillId, shardingId))
            .orElse(null);
        originalData = JsonSerializer.serialize(originalDataObject);
    } catch (Throwable ex) {
        Log.warn(ex, "日志内容补充originalData失败");
    }
}
try {
    // 业务操作
    return (result = joinPoint.proceed());
} catch (Throwable ex) {
    // 异常处理，记录错误信息
    ...
} finally {
    // 同步解析注解上的其他值，最终再交给线程池异步写入数据库，这里没有把解析处理的逻辑也异步化
    ...
}

但是由于原始数据一般都是全量的整条数据，会造成日志表的数据膨胀，且必须在操作前查询，也会影响接口性能，所以需要慎用。

可能的优化点

上面的SpEL解析代码中使用到了ThreadLocal，目前解析注解是同步处理，写数据才进入到线程池异步写，虽然实测性能问题不大，但是这里可以扩展优化一下，把解析注解值的过程也搬到线程池中去，这里就涉及到如何在线程池异步的场景下使用ThreadLocal？答案是阿里开源的TransmittableThreadLocal。