【操作日志】一次失败的系统操作日志方案设计

前言

操作日志几乎存在于每个系统中，在后台系统中属于基础能力，是一个必备功能。操作日志要做到简单易懂。 如何让操作日志不和业务逻辑耦合，如何让操作日志的内容易于理解，让操作日志的接入更加简单，这是操作日志模块设计的重点。

方案调研

通过资料查询，发现目前常见的方案，基本都是基于Spring-AOP+自定义注解实现，我在以前的系统中，也都是基于aop实现。

注解+aop

注解+aop方案有一个痛点，就是需要再每个接口上都加入一个注解，其中会包含多个参数，如果再使用SpEL表达式，会使接口上显得很混乱。 使用SpEL表达式，还会让接口层出现一些“硬编码”的存在。所以在这次的设计中，我直接抛弃了注解+aop方案。

canal

通过资料查询和gpt询问，发现有一个阿里开源的canal中间件，canal用于数据同步的业务，通过采用监听数据库 Binlog 的方式，可以从底层知道是哪些数据做了修改，然后根据更改的数据记录操作日志。 通过canal官网学习得知，canal有多种消息通知方式，包括java、Kafka、RocketMQ、RabbitMQ、PulsarMQ。

能不能通过解析canal的消息，来记录系统的操作日志？

版本控制

中间件

• canal：v1.1.7
• kafka：3.9.0
• mysql：8.0.22

Java

• jdk17
• springboot：3.3.6
• spring-kafka：3.3.0

代码实现

时序图

canal

修改canal.properties中的canal.serverMode，将通知方式改为kafka。

修改instance.properties，修改配置canal.instance.mq.topic=canal，设置发送的topic名

java

消息监听

代码中，写一个监听canal这个topic的消费者类，伪代码如下

@KafkaListener(topics = KafkaConstants.CANAL_OPERATION_TOPIC)
    public void operationLogListener(String message, Acknowledgment acknowledgment) {
        try {
            log.debug("监听canal-kafka消息，请求原串：{}", message);
            CanalLogMessage canalLogMessage = super.decodeMessage(message, CanalLogMessage.class);
            log.debug("监听canal-kafka消息，操作日志记录完成，记录条数：{}，日志：{}", saveCount, operationLogList);
        } catch (Exception e) {
            log.error("监听canal-kafka消息，操作日志记录异常：{}", e.getMessage(), e);
            throw new BusinessException("kafka 失败");
        } finally {
            acknowledgment.acknowledge();
        }
    }

CanalLogMessage定义如下

public class CanalLogMessage {

    /**
     * 修改后的对象
     */
    private List<Map<String, String>> data;

    /**
     * 修改前的对象
     * 只有type = UPDATE时才有值
     */
    private List<Map<String, String>> old;

    /**
     * 修改的时间点
     */
    private Long es;

    /**
     * 操作类型
     */
    private String type;

    /**
     * 操作表名
     */
    private String table;
}

现在可以收到mysql的变更记录了，这时出现了第一个问题

问题一

在数据库中，表一般情况会分为几种情况

• 业务表，例如user、role、menu等
• 中间关联表，例如user_role、role_menu等
• 基础设施表，例如operation_log、login_log等 对于操作日志来说，我们只会关心业务表的数据变更，那么我们应该如何区分canal发送的请求是否属于业务表呢？

解决方案

在系统常量中，定义一个需要记录日志的表集合

 /** 需要记录操作日志的表 */
    public static final List<String> NEED_RECORD_OPERATION_LOG_TABLE = Lists.newArrayList(
            "t_tenant", "t_user", "t_role", "t_menu", "t_system_properties"
    );

消费者类中，加入一个表名判断，用于决定消息是否需要处理，修改后的代码如下

@KafkaListener(topics = KafkaConstants.CANAL_OPERATION_TOPIC)
public void operationLogListener(String message, Acknowledgment acknowledgment) {
    try {
        log.debug("监听canal-kafka消息，请求原串：{}", message);
        CanalLogMessage canalLogMessage = super.decodeMessage(message, CanalLogMessage.class);

        if (!checkTable(canalLogMessage.getTable())) {
            return;
        }
       
        log.debug("监听canal-kafka消息，操作日志记录完成，记录条数：{}，日志：{}", saveCount, operationLogList);
    } catch (Exception e) {
        log.error("监听canal-kafka消息，操作日志记录异常：{}", e.getMessage(), e);
        throw new BusinessException("kafka 失败");
    } finally {
        acknowledgment.acknowledge();
    }
}

/**
 * 是否需要保存操作日志
 *
 * @param tableName 表名
 * @return boolean
 */
private boolean checkTable(String tableName) {
    if (StringUtils.isEmpty(tableName)) {
        return false;
    }
    return Constants.NEED_RECORD_OPERATION_LOG_TABLE.contains(tableName);
}

动作转换

解决了业务表问题后，现在需要将canal的消息转换为我们自己的领域对象，这里我定义了一个枚举，用于数据库的动作（创建、更新、删除）。 枚举定义如下

@Getter
@AllArgsConstructor
public enum LogOperationEnum implements EnumInterface<Integer> {
    UNKNOWN(-1, "UNKNOWN", "未知") {
        @Override
        public List<OperationLog> execute(CanalLogMessage canalLogMessage) {
            log.warn("记录操作请求日志异常，操作类型暂不支持：{}，data：{}", this, canalLogMessage);
            return Lists.newArrayList();
        }
    },
    SELECT(1, "SELECT", "查询") {
        @Override
        public List<OperationLog> execute(CanalLogMessage canalLogMessage) {
            return Lists.newArrayList();
        }
    },
    INSERT(2, "INSERT", "创建") {
        @Override
        public List<OperationLog> execute(CanalLogMessage canalLogMessage) {
            return buildLogs(canalLogMessage, this);
        }
    },
    UPDATE(3, "UPDATE", "编辑") {
        @Override
        public List<OperationLog> execute(CanalLogMessage canalLogMessage) {
            List<Map<String, String>> dataList = canalLogMessage.getData();
            List<Map<String, String>> oldDataList = canalLogMessage.getOld();

            return IntStream.range(0, Math.min(dataList.size(), oldDataList.size()))
                    .mapToObj(i -> {
                        Map<String, String> data = dataList.get(i);
                        Map<String, String> oldData = oldDataList.get(i);
                        OperationLog operationLog = LogOperationEnum.buildBasicOperationLog(data, canalLogMessage.getEs(), this);
                        operationLog.setContent(buildContent(data, oldData, this));
                        return operationLog;
                    })
                    .toList();
        }
    },
    DELETE(4, "DELETE", "删除") {
        @Override
        public List<OperationLog> execute(CanalLogMessage canalLogMessage) {
            return buildLogs(canalLogMessage, this);
        }
    },
    ;

    private final Integer code;
    private final String action;
    private final String desc;

    /**
     * 日志记录抽象方法
     *
     * @param canalLogMessage canal通知消息
     * @return 操作日志集合
     */
    public abstract List<OperationLog> execute(CanalLogMessage canalLogMessage);

    public static LogOperationEnum getByAction(String action) {
        for (LogOperationEnum operationEnum : values()) {
            if (Objects.equals(operationEnum.getAction(), action)) {
                return operationEnum;
            }
        }
        return UNKNOWN;
    }

    /**
     * 获取租户ID
     * tenant表用ID，其余表用tenantId
     *
     * @param data 字段
     * @return 租户ID
     */
    private static Long getTenantId(Map<String, String> data) {
        return Long.valueOf(data.getOrDefault("tenantId", data.get("id")));
    }

    /**
     * 获取操作人
     *
     * @param data 字段
     * @return 操作人
     */
    private static String getOperator(Map<String, String> data) {
        return data.get("updater");
    }

    /**
     * 构建基础Log信息
     *
     * @param canalLogMessage canal通知消息
     * @param operationEnum   操作类型
     * @return 操作日志集合
     */
    private static List<OperationLog> buildLogs(CanalLogMessage canalLogMessage, LogOperationEnum operationEnum) {
        return canalLogMessage.getData().stream()
                .map(data -> {
                    OperationLog operationLog = buildBasicOperationLog(data, canalLogMessage.getEs(), operationEnum);
                    operationLog.setContent(buildContent(data, null, operationEnum));
                    return operationLog;
                })
                .toList();
    }

    /**
     * 构建基础日志信息
     *
     * @param data          字段
     * @param operationTime 操作时间
     * @param operationEnum 操作类型
     * @return 操作日志
     */
    private static OperationLog buildBasicOperationLog(Map<String, String> data, Long operationTime, LogOperationEnum operationEnum) {
        return OperationLog.builder()
                .tenantId(getTenantId(data))
                .operationTime(DateUtils.getDateByMill(operationTime))
                .operationType(operationEnum.getCode())
                .operator(getOperator(data))
                .creator(getOperator(data))
                .createTime(DateUtils.now())
                .build();
    }

    /**
     * 构建操作详情
     *
     * @param data          字段
     * @param old           原字段
     * @param operationEnum 操作类型
     * @return 操作详情
     */
    private static String buildContent(Map<String, String> data, Map<String, String> old, LogOperationEnum operationEnum) {
        String operator = getOperator(data);
        String action = operationEnum.getDesc();

        if (operationEnum == UPDATE && Objects.nonNull(old)) {
            return String.format("【%s】【%s】【原数据：%s】，【新数据：%s】", operator, action, old, data);
        }
        return String.format("【%s】【%s】【%s】", operator, action, data);
    }

}

在枚举中，我们进行了不同动作的参数转换，比如更新操作，需要同时记录更新前和更新后的数据，转换后进行数据落库，此时我们再更新消费者的代码，修改如下

@KafkaListener(topics = KafkaConstants.CANAL_OPERATION_TOPIC)
    public void operationLogListener(String message, Acknowledgment acknowledgment) {
        try {
            log.debug("监听canal-kafka消息，请求原串：{}", message);
            CanalLogMessage canalLogMessage = super.decodeMessage(message, CanalLogMessage.class);

            if (!checkTable(canalLogMessage.getTable())) {
                return;
            }

            LogOperationEnum logOperationEnum = LogOperationEnum.getByAction(canalLogMessage.getType());
            List<OperationLog> operationLogList = logOperationEnum.execute(canalLogMessage);

            log.info("监听canal-kafka消息，请求原串：{}", message);
            Integer saveCount = operationLogRepository.batchSave(operationLogList);

            log.debug("监听canal-kafka消息，操作日志记录完成，记录条数：{}，日志：{}", saveCount, operationLogList);
        } catch (Exception e) {
            log.error("监听canal-kafka消息，操作日志记录异常：{}", e.getMessage(), e);
            throw new BusinessException("kafka 失败");
        } finally {
            acknowledgment.acknowledge();
        }
    }

此时，我们的大体消费流程已经完成了，可以实现优雅的操作日志记录了。

消费失败

细心的同学已经发现了，我们再finally中使用了手动ack，那么如果上面的业务代码出错了，我们要怎么处理，难道这条数据变更消息就不进行记录了吗？那肯定是不行的，如果直接抛弃，那么我们记录的操作日志也没有意义了。

消息重试+死信队列

我们修改kafka配置，加入重试及死信队列，代码如下

@Component
public class KafkaConfig {

    @Value("${spring.kafka.max-attempts:3000}")
    private Long maxAttempts;

    @Value("${spring.kafka.interval:3}")
    private Long interval;

    @Bean
    public KafkaListenerContainerFactory<?> kafkaListenerContainerFactory(ConsumerFactory<String, String> consumerFactory,
                                                                          KafkaTemplate<String, String> kafkaTemplate) {
        ConcurrentKafkaListenerContainerFactory<String, String> factory = new ConcurrentKafkaListenerContainerFactory<>();

        // 自定义死信队列
        DeadLetterPublishingRecoverer recoverer = new DeadLetterPublishingRecoverer(
                kafkaTemplate,
                (record, ex) -> {
                    log.error("消息消费失败，发送至死信队列: topic={} partition={}", record.topic(), record.partition());
                    return new TopicPartition("canal-dlt", record.partition());
                });

        // 自定义失败重试次数
        factory.setCommonErrorHandler(new DefaultErrorHandler(recoverer,
                new FixedBackOff(interval, maxAttempts)
        ));

        // 手动ack
        factory.getContainerProperties().setAckMode(ContainerProperties.AckMode.MANUAL);

        factory.setConsumerFactory(consumerFactory);

        return factory;
    }
}

上面代码中，在配置文件中加入spring.kafka.max-attempts和spring.kafka.interval配置，用于定义重试次数及重试间隔时间，并使用recoverer来设置死信队列，用于处理重试失败的数据。在伪代码中，operationLogListener消费失败的数据，会进行3次重试，每次重试间隔3秒，3次重试失败后，会将消息发送给canal-dlt这个topic，再由另外的消费者去监听。

死信队列监听

死信队列中，我们通过对record的解析，拿到消费失败队列的原始topic、key、message数据，并将其持久化到数据库中，以便于后续分析。

@KafkaListener(topics = KafkaConstants.DEAD_LETTER_QUEUE_TOPIC)
    public void handleDltMessage(ConsumerRecord<String, String> record, Acknowledgment acknowledgment) {
        try{
            KafkaDeadMessage kafkaDeadMessage = KafkaDeadMessage.builder()
                    .kafkaTopic(getOriginalTopic(record.headers()))
                    .kafkaPartition(String.valueOf(record.partition()))
                    .status(KafkaDeadMessageStatusEnum.NOT_RETRY.getCode())
                    .kafkaKey(record.key())
                    .kafkaValue(record.value())
                    .build();

            kafkaDeadMessageRepository.save(kafkaDeadMessage);

            acknowledgment.acknowledge();
        } catch (Exception e){
            log.error("死信队列消息，操作死信队列数据异常：{}", e.getMessage(), e);
        }
    }

    /**
     * 获取原始topic
     * @param headers kafka header
     * @return 原始topic
     */
    private String getOriginalTopic(Headers headers) {
        if (headers != null) {
            for (Header header : headers) {
                if ("kafka_dlt-original-topic".equals(header.key())) {
                    return new String(header.value(), StandardCharsets.UTF_8);
                }
            }
        }
        return StringUtils.EMPTY;
    }

消费失败补偿

死信队列的数据存储到数据库中，我们加入一个定时任务，定期尝试重试失败的任务，伪代码如下

    @Scheduled(cron = "0 */10 * * * ?")
    public void kafkaCompensateTask() {
        List<KafkaDeadMessage> list = kafkaDeadMessageRepository.list(KafkaDeadMessageStatusEnum.needRetryStatus());
        // 异步执行消息重试
        ConcurrentUtils.async(() -> list.forEach(this::pushToKafka));
    }

    private void pushToKafka(KafkaDeadMessage kafkaDeadMessage) {
        try {
            JSONObject kafkaValue = JSONObject.parseObject(kafkaDeadMessage.getKafkaValue());
            kafkaValue.put(KafkaConstants.RETRY_COMPENSATE_ID, kafkaDeadMessage.getId());
            kafkaValue.put(KafkaConstants.RETRY_COMPENSATE_KEY, true);
            kafkaProducer.publish(kafkaDeadMessage.getKafkaTopic(), kafkaValue.toJSONString());
        } catch (Exception e) {
            log.error("kafka消息补偿定时任务异常，messageId: {}, 原因是：{}", kafkaDeadMessage.getId(), e.getMessage(), e);
            kafkaDeadMessageRepository.update(kafkaDeadMessage.getId(), KafkaDeadMessageStatusEnum.RETRY_FAIL);
        }
    }

KafkaDeadMessageStatusEnum枚举定义

@Getter
@AllArgsConstructor
public enum KafkaDeadMessageStatusEnum implements EnumInterface<Integer> {
    NOT_RETRY(0, "未重试"),
    RETRY_SUCCESS(1, "重试成功"),
    RETRY_FAIL(2, "重试失败"),
    ;
    private final Integer code;
    private final String desc;

    @Override
    public Boolean exist(Integer code) {
        return Stream.of(values()).anyMatch(s -> s.getCode().equals(code));
    }

    public static List<KafkaDeadMessageStatusEnum> needRetryStatus() {
        return Lists.newArrayList(NOT_RETRY, RETRY_FAIL);
    }
}

我们从表中读取出失败的topic及数据，重新发送给对应的队列中，并在请求数据中加入RETRY_COMPENSATE_ID和RETRY_COMPENSATE_KEY两个参数，用来标记本次的消息是定时补偿任务发送的，此时对应topic的消费者代码也需要对应的调整，最终修改如下

@KafkaListener(topics = KafkaConstants.CANAL_OPERATION_TOPIC)
public void operationLogListener(String message, Acknowledgment acknowledgment) {
    try {
        log.debug("监听canal-kafka消息，请求原串：{}", message);
        CanalLogMessage canalLogMessage = super.decodeMessage(message, CanalLogMessage.class);

        if (!checkTable(canalLogMessage.getTable())) {
            return;
        }

        LogOperationEnum logOperationEnum = LogOperationEnum.getByAction(canalLogMessage.getType());
        List<OperationLog> operationLogList = logOperationEnum.execute(canalLogMessage);

        log.info("监听canal-kafka消息，请求原串：{}", message);
        Integer saveCount = operationLogRepository.batchSave(operationLogList);

        // 如果是补偿任务，需要更新补偿任务表的状态
        checkRetryTask(canalLogMessage);

        log.debug("监听canal-kafka消息，操作日志记录完成，记录条数：{}，日志：{}", saveCount, operationLogList);
    } catch (Exception e) {
        log.error("监听canal-kafka消息，操作日志记录异常：{}", e.getMessage(), e);
        throw new BusinessException("kafka 失败");
    } finally {
        acknowledgment.acknowledge();
    }
}

private void checkRetryTask(BaseMessage message) {
    // 如果是补偿任务，需要更新补偿任务表的状态
    if (isRetryTask(message.getIsRetry())) {
        log.info("监听canal-kafka消息，请求原串：{}", message);
        updateKafkaDeadMessage(message.getMessageId());
    }
}

private boolean isRetryTask(Boolean isRetry) {
    return Objects.nonNull(isRetry) && isRetry;
}

private void updateKafkaDeadMessage(Long messageId) {
    if (Objects.isNull(messageId)) {
        return;
    }
    kafkaDeadMessageRepository.update(messageId, KafkaDeadMessageStatusEnum.RETRY_SUCCESS);
}

代码总结

现在看下来我们实现了一个与业务逻辑、代码完全分离的操作日志模块，看起来满足了我们最开始的需求。

问题二

在系统最初的设计中，只考虑了操作类型、操作人、操作内容、操作时间几项，忽略了一个重要因素，那就是本次操作的操作模块。 那么如何将canal的消息和所属模块对应起来？

canal的消息，会将变更的表明通过【table】字段发送过来，可是如何将英文的表名和业务对应的中文映射起来？ 这里没有找到好的方案，最简单的办法是，在系统常量或Redis中，维护一个KV格式的对象，迎来映射表名和业务名。

问题三

canal不能支持一个业务中的多表操作，例如下面的用户授权的动作

public void doExecute(PermissionUserRequest request, BaseResponse<Boolean> response) {
    Long userId= request.getId();
    valid(request);
    // 清空原权限
    userRoleRepository.removeByUserId(userId);
    UserRole userRole = UserRoleAssembler.INSTANCE.convert(request);
    Integer saveFlag = userRoleRepository.save(userRole);
    // 清空token，重新登录
    super.removeToken(Lists.newArrayList(userId));
    response.setData(checkFlag(saveFlag));
}

如果我们在代码中先清空用户的角色，再重新插入，这对于canal来说，是两次变更动作，会发送两次kafka变更消息，这对于我们的消费者来说是灾难性的，因为我们不能将属于一个业务操作的两次消息绑定起来。

总结

目前看下来，canal记录操作日志的方案行不通，看来各司其职还是有道理的，canal的使用场景还是在数据同步的方向。

最终的方案还是采用了aop+注解+SpEL实现，还是传统的方案经历过实践检验，更加通用，后续在深入研究canal后，再尝试能否优化上面的方案，使业务日志与代码真正的解耦。

虽然MySQL、Kafka、Canal都是项目中已经在使用的中间件，但是上面的设计还是使代码变得更加复杂，还需要考虑数据补偿、消费失败等场景，看来还是不要过度设计才行。