如何优雅地记录 *** 作日志？

1 前言

        在日常的工作开发中，记录业务 *** 作产生的日志是很普遍的 *** 作。通过它可以看到每条数据产生的变化，也能在出现问题的时候快速找到原因。

        对于我自己而言，因为我这里记录的日志需要进行一些逻辑判断，并不是简单的一条条文本数据。所以像我之前的写法是将记录日志的代码和业务代码都写在同一个方法中，这样就显得很乱。我一直都想要改造这块，但是却没有一个很好的思路，网上的一些实现方案也不能达到我的预期，所以就一直这么放下了。后来偶然间看到了美团技术团队的一篇文章《如何优雅地记录 *** 作日志？》（我这里斗胆使用了相同的标题），从中获得了很大的启发，借用了其中的一些思想和套路，写出了自己的实现，在这里与大家分享。

        在这里十分感谢这篇文章的作者，同时我这里也只是借用了他的一些实现思路，具体的代码实现和美团的不太一样，美团的这篇文章也并没有给出所有代码的具体实现。与其说照着别人的思路往下写，还不如自己重头开发。因为是别人的思路，所以很有可能出现写到一半写不下去的情况。自己进行开发，思路都是自己的，对于二次开发来说也更加得心应手。

        相比于美团的版本，我这个版本在功能上做了一些阉割和调整，现在的实现已经能满足公司业务的需要，等后期有时间的话再进行补充和完善。

        还有一点需要说明的是：我这里记录的日志是偏向于业务侧的日志，而不是功能性的日志。相比于功能性日志，业务日志因其记录内容的灵活多变，往往更难封装。

        完整的代码已放到GitHub：https://github.com/MonkeyOneCool/MyLogRecord

---

2 功能 2.1 快速使用

import com.hys.mylogrecord.customfunction.MyLogRecordSnapshotFunction;
import com.hys.mylogrecord.log.OperationLogTypeEnum;
import com.hys.mylogrecord.util.LogRecordUtils;

import java.lang.annotation.*;

/**
 * 日志记录
 *
 * @author Robert Hou
 * @since 2022年04月21日 19:37
 **/
@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface MyLogRecord {

    /**
     * 日志类型
     */
    OperationLogTypeEnum type();

    /**
     * 关联主键id
     */
    @SpelDynamicTemplate
    @CustomFunction
    String relationId() default "";

    /**
     *  *** 作人id
     */
    @SpelDynamicTemplate
    @CustomFunction
    String operatorId() default "";

    /**
     *  *** 作说明
     */
    @SpelDynamicTemplate
    @CustomFunction
    String description() default "";

    /**
     * 保存快照，返回值会被存进缓存中。需要实现{@link MyLogRecordSnapshotFunction}接口，通过{@link LogRecordUtils#getSnapshotCache()}方法拿到缓存值
     * 注：本方法会比预处理的自定义函数还要先执行，同时也就意味着在自定义函数预执行阶段即可拿到缓存值
     */
    @SpelDynamicTemplate
    @CustomSnapshotFunction
    String snapshot() default "";
}

        以上是日志记录的注解，除了最后的snapshot配置项之外，其他的都是业务侧的参数，很好理解。snapshot配置项放在后面的章节再进行讲解。另外，除了type配置项之外，其他的配置项都不是必填的，以此来简化使用。愿景是希望能做到不侵入一行业务代码，并且使用起来很方便，不需要太多的配置项内容。

        简单的demo如下：

@MyLogRecord(
        type = OperationLogTypeEnum.INSERT_PRODUCT,
        relationId = "123",
        operatorId = "456",
        description = "添加商品")
public void simpleTest() {
    log.info("执行业务 *** 作...");
}

        运行结果：

2022-04-26 20:11:16.004  INFO 11052 --- [           main] c.hys.mylogrecord.demo.MyLogRecordTest   : 执行业务 *** 作...
2022-04-26 20:11:16.010  INFO 11052 --- [         task-1] c.h.m.p.s.i.DefaultLogRecordServiceImpl  : operationLogDTO:OperationLogDTO(id=null, type=1, relationId=123, operatorId=456, operateTime=Tue Apr 26 20:11:16 CST 2022, description=添加商品)

        实际的 *** 作记录是需要入库的，我这里就用打印日志来进行代替。可以看到，日志实体里的属性被成功赋值。

2.2 动态文本解析

        上面例子中的注解上的配置项都是静态文本。而在我们实际的开发中，是不可能这么简单的。所以这里就用到了动态文本解析的功能：

@MyLogRecord(
        type = OperationLogTypeEnum.INSERT_PRODUCT,
        relationId = "{#spuId}",
        operatorId = "{#operatorId}",
        description = "添加商品 {#productContentDTO.content}")
public void dynamicTemplateTest(Long spuId, Long operatorId, ProductContentDTO productContentDTO) {
    log.info("执行业务 *** 作...");
}

        测试类如下：

@Test
void contextLoads() {
    ProductContentDTO productContentDTO = new ProductContentDTO();
    productContentDTO.setContent("商品参数");
    myLogRecordTest.dynamicTemplateTest(123L, 456L, productContentDTO);
}

        运行结果：

2022-04-26 20:48:05.286  INFO 12612 --- [           main] c.hys.mylogrecord.demo.MyLogRecordTest   : 执行业务 *** 作...
2022-04-26 20:48:05.306  INFO 12612 --- [           main] c.h.m.p.s.i.DefaultLogRecordServiceImpl  : operationLogDTO:OperationLogDTO(id=null, type=1, relationId=123, operatorId=456, operateTime=Tue Apr 26 20:48:05 CST 2022, description=添加商品 商品参数)

        可以看到，日志实体里的属性值都被动态替换掉了。我这里解析参数使用的是SpEL的语法和API，需要说明的一点是：“#”后面跟着的参数需要和业务方法上的参数名一一对应，否则不会进行识别。

2.3 回调自定义函数

        如果 *** 作日志上的动态参数很简单的话、通过业务方法上的参数即可完成拼接，那么确实可以使用上面的语法规则来进行快捷 *** 作。但是很多的情况下是需要自己写一些复杂的逻辑来进行拼接的，这个时候就可以使用自定义函数的功能。首先需要创建一个bean，实现MyLogRecordFunction接口，MyLogRecordFunction接口的代码如下：

/**
 * 日志记录自定义函数
 * 注：实现类必须定义成Spring Bean的形式
 *
 * @author Robert Hou
 * @since 2022年04月23日 11:27
 **/
public interface MyLogRecordFunction {

    /**
     * 是否在目标方法前执行
     */
    default boolean executeBefore() {
        return false;
    }

    /**
     * 方法名
     * 注：需要保证全局唯一，建议加上项目名前缀
     */
    String functionName();

    /**
     * 自定义函数
     */
    String apply(Object value);
}

        executeBefore方法是用来控制自定义函数的执行时机是在业务方法之前还是之后。functionName是用来作为自定义函数的唯一标识，如果名称重复的话会进行覆盖。apply方法即为自定义函数，通过executeBefore方法的返回值来确定回调的时机。

        实现类如下所示：

import com.hys.mylogrecord.customfunction.MyLogRecordFunction;
import org.springframework.stereotype.Component;

/**
 * 添加商品 *** 作说明
 *
 * @author Robert Hou
 * @since 2022年04月26日 22:49
 **/
@Component
public class InsertProductDescLogRecordFunction implements MyLogRecordFunction {

    @Override
    public String functionName() {
        return "product_insertProduct_desc";
    }

    @Override
    public String apply(Object value) {
        String content;
        if (value instanceof String) {
            content = (String) value;
        } else {
            return null;
        }

        return content + "123";
    }
}

        apply方法上的value参数即为在注解上传过来的值，之后会看到。这里演示的效果是对content进行了简单的拼接 *** 作，然后返回。实际上可以进行任何的复杂 *** 作，因为是个bean，所以可以调用其他的接口来实现更复杂的逻辑。需要注意的是：即使apply方法的实现很简单、不需要调用其他接口的话，也仍然需要注册成bean对象。因为我在项目启动的时候只会扫描bean对象，并加载进缓存中，Class对象是不会进行缓存的。

@MyLogRecord(
        type = OperationLogTypeEnum.INSERT_PRODUCT,
        relationId = "{#spuId}",
        operatorId = "{#operatorId}",
        description = "添加商品 {product_insertProduct_desc{#productContentDTO.content}}")
public void customFunctionTest(Long spuId, Long operatorId, ProductContentDTO productContentDTO) {
    log.info("执行业务 *** 作...");
}

        注解的使用如上所示，可以看到，相比于动态文本解析的版本，只是在description配置项里对{#productContentDTO.content}再进行了一层包装，这里的“product_insertProduct_desc”即为上面InsertProductDescLogRecordFunction自定义函数里的functionName。需要注意的是：自定义函数和动态文本解析一样，需要用大括号包围住才能进行识别。不同的是，自定义函数名前不能有“#”，否则就会识别成动态文本解析了。自定义函数的functionName只能输入数字、大小写字母、下划线和“$”，在项目启动的时候会进行校验。

        下面来看下执行结果：

2022-04-26 23:26:30.073  INFO 36996 --- [           main] c.hys.mylogrecord.demo.MyLogRecordTest   : 执行业务 *** 作...
2022-04-26 23:26:30.154  INFO 36996 --- [           main] c.h.m.p.s.i.DefaultLogRecordServiceImpl  : operationLogDTO:OperationLogDTO(id=null, type=1, relationId=123, operatorId=456, operateTime=Tue Apr 26 23:26:30 CST 2022, description=添加商品 商品参数123)

        可以看到“商品参数”后面是拼接了“123”的。下面来看另一个例子，这个例子可以更好地说明自定义函数存在的意义。现在我要修改商品，记录的日志格式为“修改前：xxx，修改后：xxx”，那么对于这个例子，我需要写两个自定义函数，一个是业务方法执行前，一个是业务方法执行后：

import com.hys.mylogrecord.customfunction.MyLogRecordFunction;
import org.springframework.stereotype.Component;

/**
 * 修改商品 *** 作说明（目标方法前执行）
 *
 * @author Robert Hou
 * @since 2022年04月27日 00:07
 **/
@Component
public class UpdateProductDescExecuteBeforeLogRecordFunction implements MyLogRecordFunction {

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

    @Override
    public String functionName() {
        return "product_updateProduct_desc_executeBefore";
    }

    @Override
    public String apply(Object value) {
        return "业务方法执行前的" + value;
    }
}

import com.hys.mylogrecord.customfunction.MyLogRecordFunction;
import org.springframework.stereotype.Component;

/**
 * 修改商品 *** 作说明（目标方法后执行）
 *
 * @author Robert Hou
 * @since 2022年04月26日 23:49
 **/
@Component
public class UpdateProductDescExecuteAfterLogRecordFunction implements MyLogRecordFunction {

    @Override
    public String functionName() {
        return "product_updateProduct_desc_executeAfter";
    }

    @Override
    public String apply(Object value) {
        return "业务方法执行后的" + value;
    }
}

        可以看到，UpdateProductDescExecuteBeforeLogRecordFunction相比于UpdateProductDescExecuteAfterLogRecordFunction多覆写了executeBefore方法，使其返回true，代表业务方法执行前进行回调。

        具体的使用如下：

@MyLogRecord(
        type = OperationLogTypeEnum.UPDATE_PRODUCT,
        relationId = "{#spuId}",
        operatorId = "{#operatorId}",
        description = "修改商品 修改前：“{product_updateProduct_desc_executeBefore{#productContentDTO.content}}”，修改后：“{product_updateProduct_desc_executeAfter{#productContentDTO.content}}”")
public void anotherCustomFunctionTest(Long spuId, Long operatorId, ProductContentDTO productContentDTO) {
    log.info("执行业务 *** 作...");
}

        运行结果：

2022-04-27 00:21:52.884  INFO 1248 --- [           main] c.hys.mylogrecord.demo.MyLogRecordTest   : 执行业务 *** 作...
2022-04-27 00:21:52.884  INFO 1248 --- [           main] c.h.m.p.s.i.DefaultLogRecordServiceImpl  : operationLogDTO:OperationLogDTO(id=null, type=2, relationId=123, operatorId=456, operateTime=Wed Apr 27 00:21:52 CST 2022, description=修改商品 修改前：“业务方法执行前的商品参数”，修改后：“业务方法执行后的商品参数”)

2.4 全局缓存

        在对公司项目代码进行切换成日志注解方式的过程中，我发现了有一种情况是不能满足的，这也就触发了我实现全局缓存的功能。在一些场景中，我并不是要记录“修改前：xxx，修改后：xxx”格式的日志，而是要具体记录到底是哪个字段发生了修改，哪个字段删除了，类似这样格式的日志。这个需求如果是通过之前的自定义函数和动态文本解析是实现不了的，但是实现不了的原因不光是因为目前的自定义函数不支持多个参数传入，更重要的原因是因为这里需要对多个实体的执行时机进行区分，第一个实体是需要在业务方法执行前获取，而第二个实体是需要在业务方法执行后获取。最后拿到这两个实体，再进行比对。

        借用开头引用的美团文章里的一句话，遇到这种情况下你可以去和产品经理PK，但是大多数情况下你是不可能成功说服的，因为这个需求确实很合理。即使能说服，对于一个有着高要求的程序员来说也是不能妥协的，必须要想办法兼容。

        这里的解决办法有很多种，比如说可以对自定义函数进行多参数传入的改造，同时动态文本解析需要和自定义函数一样，支持执行时机的区分。但是这种方案对于我来说实现的代价太大了，对于使用者来说也更加繁琐。我最后的实现方案是增加全局缓存的功能，也就是上面MyLogRecord注解里的snapshot配置项的作用。snapshot里面也可以配置自定义函数和动态文本解析（如果是静态文本的话，不会起任何作用），但是这个方法返回的结果并不会用于日志展示，而是会被缓存进ThreadLocal中，在当前方法的整个调用期间有效。同时snapshot配置项的返回值会比预处理的自定义函数还要先执行，这也就意味着在自定义函数预执行阶段即可拿到缓存值。

        跟自定义函数类似，实现全局缓存也需要实现一个接口：MyLogRecordSnapshotFunction：

import com.hys.mylogrecord.util.LogRecordUtils;

/**
 * 日志记录保存快照
 * 注：实现类必须定义成Spring Bean的形式
 *
 * @author Robert Hou
 * @since 2022年04月25日 17:45
 **/
public interface MyLogRecordSnapshotFunction {

    /**
     * 方法名
     * 注：需要保证全局唯一，建议加上项目名前缀
     */
    String functionName();

    /**
     * 自定义函数
     * 注：本方法的返回值会被存进缓存中，通过{@link LogRecordUtils#getSnapshotCache()}方法拿到缓存值
     */
    Object snapshotApply(Object value);
}

        可以看到，这个接口和之前的MyLogRecordFunction接口是很类似的，只不过是没有executeBefore方法而已。这是因为MyLogRecordSnapshotFunction接口的执行时机固定是在最前面。同时还有一个细节不同就是：MyLogRecordSnapshotFunction的snapshotApply方法因为是用来做缓存的，任何类型的数据都可以进行缓存，所以返回值是Object类型；而MyLogRecordFunction的apply方法的返回值是用来做日志展示用的，所以写死为String类型。

         实现类如下所示：

import com.hys.mylogrecord.customfunction.MyLogRecordSnapshotFunction;
import com.hys.mylogrecord.demo.dto.ProductContentDTO;
import org.springframework.stereotype.Component;

/**
 * 修改商品保存快照
 *
 * @author Robert Hou
 * @since 2022年04月27日 01:38
 **/
@Component
public class UpdateProductLogRecordSnapshotFunction implements MyLogRecordSnapshotFunction {

    @Override
    public String functionName() {
        return "product_updateProduct_snapshot";
    }

    @Override
    public Object snapshotApply(Object value) {
        Long spuId;
        if (value instanceof Long) {
            spuId = (Long) value;
        } else {
            return null;
        }

        ProductContentDTO productContentDTO = new ProductContentDTO();
        productContentDTO.setContent("执行业务方法前的实体");
        return productContentDTO;
    }
}

        可以看到这里是将一个ProductContentDTO实体放进了缓存中，下面来看下description配置项配置的自定义函数：

import com.hys.mylogrecord.customfunction.MyLogRecordFunction;
import com.hys.mylogrecord.demo.dto.ProductContentDTO;
import com.hys.mylogrecord.util.LogRecordUtils;
import org.apache.commons.collections4.CollectionUtils;
import org.apache.commons.lang3.StringUtils;
import org.springframework.stereotype.Component;

import java.util.List;
import java.util.Objects;

/**
 * 修改商品 *** 作说明
 *
 * @author Robert Hou
 * @since 2022年04月27日 01:44
 **/
@Component
public class UpdateProductDescLogRecordSnapshotFunction implements MyLogRecordFunction {

    @Override
    public String functionName() {
        return "product_updateProduct_desc_snapshot";
    }

    @Override
    public String apply(Object value) {
        List