使用zipkin排查springClouod微服务之间接口调用超时并重试导致数据重复插入问题

最新推荐文章于 2022-12-25 16:21:11 发布

icetea916

最新推荐文章于 2022-12-25 16:21:11 发布

阅读量1k

点赞数

分类专栏： Java Spring 文章标签： spring

本文链接：https://blog.csdn.net/tengblacktea/article/details/118763305

版权

Java 同时被 2 个专栏收录

9 篇文章 0 订阅

订阅专栏

Spring

1 篇文章 0 订阅

订阅专栏

本文探讨了mq-consumer服务在处理class服务响应超时时的重试机制导致的重复数据插入问题。通过调整ribbon和hystrix的超时时间，以及分析链路追踪，作者解决了这个问题并提供了详细解决方案。

摘要由CSDN通过智能技术生成

问题描述

错误记录如下

视频观看记录表中插入了三条开始时间、结束时间、观看时长一模一样的数据，记录如下：

id	start_time	end_time	time
77784473	2021-07-13 11:22:29	2021-07-13 11:37:30	901
77784474	2021-07-13 11:22:29	2021-07-13 11:37:30	901
77784475	2021-07-13 11:22:29	2021-07-13 11:37:30	901

问题分析

插入观看记录的流程是这样的：

根据流程和代码分析，有2种可能会导致插入重复的数据。

websocket断开时重复发送消息至rabbitMQ队队列
mq-consumer消费服务重复消费消息,即进行了重试

排查问题1. websocket消息是否多次将同一消息入队

查看代码发现websocket断开连接将消息入队时都会打印info日志，所以查看info日志使否有多个相同的消息就能知道是否多次入队。
代码片段如下：

······
logger.info("发送观看记录消息, token={}, userId={}, key={}, sessionId={}, lookJson={}", token, userId, key, sessionId, lookJSON.toJSONString());
rabbitMqUtil.sendMessage(Queues.PC_LOOK_TIME_QUEUE, lookJSON.toJSONString());
······

日志如下：

2021-07-13 11:51:32.965 [nioEventLoopGroup-3-5] INFO handler.LookVideoListennter - 发送观看记录消息, sessionId=71689a0c-03dd-4be0-9cfb-10d8ef2e0213, lookJson={“errcode”:200,“watchTime”:901,“startTime”:1626146549684,“endTime”:1626147450685}

查看info日志后发现只有一条入队的记录，也就是说websocket服务没有多次重复入队，所以问题1排除。

排查问题2. mq-consumer消费服务是否进行了重试

查看mq-consumer消费服务业务逻辑，3次重试机制代码片段如下：

// 重试机制 代码片段
/**
* 消费者处理消息方法，自动重新入队方法
*
* @param message          消息（消息头+消息体）
* @param jsonObject       消息体
* @param dlxRoutingKey    死信队列路由键（一般为死信队列名称）
* @param messageProcessor 消息处理器
*/
public void handleMessageWithRetry(Message message, JSONObject jsonObject, String dlxRoutingKey, MessageProcessor messageProcessor) {
    MessageProperties messageProperties = message.getMessageProperties();
    Map<String, Object> headers = messageProperties.getHeaders();// 获取自定义头信息
    try {
        // 实际消息处理方法，如果该方法异常则会进行重试
        messageProcessor.processMessage(jsonObject);
    } catch (Exception e) {
        // 处理出现异常,进行重试
        int retryTimes = headers.containsKey(RETRY_HEAD_KEY) ? (int) headers.get(RETRY_HEAD_KEY) : 0;
        int nextRetryTimes = retryTimes + 1;
        if (nextRetryTimes > MAX_RETRY_TIMES) {
            // 超出最大尝试次数，将其放置到死信队列,并保存错误信息
            this.rabbitTemplate.convertAndSend(DEFAULT_DLX, dlxRoutingKey, message,
                    (Message msg) -> {
                        // 记录异常信息
                        msg.getMessageProperties().setHeader("x-exception-message", e.getCause() != null ? e.getCause().getMessage() : e.getMessage());
                        // 记录异常栈
                        msg.getMessageProperties().setHeader("x-exception-stacktrace", getStackTraceString(e));
                        // 记录异常入队时间
                        msg.getMessageProperties().setHeader("x-exception-time", new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date()));
                        return msg;
                    });
            LOGGER.error("message={} 已超过最大重试次数，放置到死信队列中", new String(message.getBody()));
        } else {
            // 入队重试
            this.rabbitTemplate.convertAndSend(messageProperties.getReceivedExchange(), messageProperties.getConsumerQueue(),
                    message, (Message msg) -> {
                        // 更新重试次数
                        msg.getMessageProperties().setHeader(RETRY_HEAD_KEY, nextRetryTimes);
                        return msg;
                    });
            LOGGER.info("message={}处理失败，进行第 {} 次重试", new String(message.getBody()), nextRetryTimes);
        }
    }
}

// 消费消息代码片段
····
rabbitMqUtil.handleMessageWithRetry(message, jsonObject, RabbitMqConstant.DLQ_LOOK_TIME_PC, this::handleMessage);
·····


// 实际处理消息代码片段
/**
* 处理pc观看记录的具体方法
*
* @param jsonObject 消息
*/
public void handleMessage(JSONObject jsonObject) {
    RequestDTO requestDTO = new RequestDTO();
    requestDTO.setData(jsonObject); // 封装消息
    ResponsDTO responsDTO = classFegin.update(requestDTO); // 请求class服务进行处理
    ResponsDTO.Message responseDTOMessage = responsDTO.getMessage();
    /**
    以下代码可以看出，只有当class远程服务返回码不是200是才会报错或者调用超时报异常才会重试
    */
    if (!responseDTOMessage.getErrcode().equals(200)) {
        throw new ServiceException(responseDTOMessage.getErrcode() + "-" + responseDTOMessage.getErrinfo() + "-" + responsDTO.getData());
    }
}

查看消费端代码可以看出当consumer消息重试时会记录info日志，查看是否有重试的info日志：

2021-07-13 11:51:34.972 [SimpleAsyncTaskExecutor-2] INFO RabbitMqUtil - message={“errcode”:200,“sessionId”:“71689a0c-03dd-4be0-9cfb10d8ef2e0213”,“watchTime”:901,“startTime”:1626146549684,“allowTime”:16800}处理失败，进行第 1 次重试

查询到一条重试日志，说明该消息只重试了一次，但是可惜没有打印异常信息，它可以判断是否调用超时（已优化该log记录打印更多异常信息），如果调用超时导致mq-consumer重试有可能会造成重复插入数据的结果，因为mq-cosumer调用超时的话会自动中断，但是class接口已经被调用并且还在执行，所以重试会造成class接口重复插入相同数据。但是为什么重试了1次但有3条一样的数据，需要进一步分析。

测试环境复现问题

从mq-consumer服务的重试日志看出了问题，为了更好地进行分析，所以要在测试环境复现一下问题，要使mq-consumer出现超时异常，则要使class服务处理时间编程，使用Thread.sleep(10000)人为造成mq-consumer超时，然后进行测试。

测试结果如下：

id	start_time	end_time	time
77169409	2021-07-15 13:51:00	2021-07-15 13:51:48	47
77169410	2021-07-15 13:51:00	2021-07-15 13:51:48	47
77169411	2021-07-15 13:51:00	2021-07-15 13:51:48	47
77169412	2021-07-15 13:51:00	2021-07-15 13:51:48	47
77169413	2021-07-15 13:51:00	2021-07-15 13:51:48	47
77169414	2021-07-15 13:51:00	2021-07-15 13:51:48	47

数据插入了6条时间一模一样的记录，······淡定，冷静分析

使用zipkin链路追踪排查重复调用问题

有这么多重复数据说明不光mq的重试机制进行了重试，其他地方也进行了重试（框架内部），刚刚配置好了zipkin链路追踪，用这个查询一下链路的调用情况，tranceId=ec7c002a75e307ce, 部分链路调用如下图：
在这里插入图片描述根据链路情况分析：

mq-consumer消费者调用class处理消息时，在一次hystrix中post调用了两次class服务，我猜hystrix或者feign有某种重试机制导致调用重试了一次。 但是查看mq关于hystrix和feign的配置没有发现关于重试次数的配置，只有超时时间的设置。
on-message应该是消费消息，因为超时又被重试了三次。

修改ribbon重试次数解决hystrix错误重试问题

没有思路先静下来思考一下，在springCloud服务间调用时通常都用到ribbon，hystrix，feign这三个组件，所以开始找资料研究一下这三个组件的关系。参考资料如下：
《Feign Ribbon Hystrix 三者关系，史上最全深度解析》

从该资料得知，ribbon组件有重试次数的配置，且默认重试次数为1次，这就验证了之前hystrix里会重试两次的结果；接下来修改mq-consumer服务中ribbon的重试次数，将次数修改成0，再测试一下。

修改配置如下：

ribbon:
  #说明：同一台实例的最大自动重试次数，默认为1次，不包括首次
  MaxAutoRetries: 0
  #说明：要重试的下一个实例的最大数量，默认为1，不包括第一次被调用的实例
  MaxAutoRetriesNextServer: 0

测试结果如下：

id	start_time	end_time	time
77169415	2021-07-15 16:25:44	2021-07-15 16:26:12	28
77169416	2021-07-15 16:25:44	2021-07-15 16:26:12	28
77169417	2021-07-15 16:25:44	2021-07-15 16:26:12	28
77169418	2021-07-15 16:25:44	2021-07-15 16:26:12	28

部分链路截图如下,tranceId=c862d7fb2b9a30a6：
在这里插入图片描述根据数据库记录和链路调用情况看出，修改ribbon的重试次数已经生效了，hystrix已经里只有一次调用且超时后没有进行重试。 post请求超时导致mq-consumer服务一共重试了3次，再加上最初的一次调用，导致这个消息一共调用了4次class服务的接口，从链路中的on-message标签可以看出，所以插入4条重复记录是意料中的结果。

接下来就是解决mq-consumer服务调用别的服务超时触发了自己写的重试机制导致的重复调用问题。

解决mq-consumer服务调用其他服务超时导致重试问题

详细问题描述

mq-consumer服务调class服务超时异常，导致hystrix中断调用且触发了自己写的重试机制，但是class服务逻辑已经执行了，最终导致的数据被重复插入。

解决方法

目前想到的解决方案：

增加mq-consumer服务的ribbon和hystrix的超时时间，保证class服务接口在超时时间内已经返回结果
在mq-consumer服务中去掉自己写的消息重试机制
修改class服务接口逻辑保证幂等性

第一种方式简单，只是修改一下配置，并且就是这个原因才导致线上bug。原来的mq消费服务没有配置的ribbon超时时间readTimeout，使用默认的readTimeout=3000ms，太短了所以会在线上class服务压力大的时候会造成超时重试。

第二种方式不太好，最好不要去掉重试机制，因为如果不是超时错误而是其他异常或错误导致消费失败的话，那么没有重试机制，就会丢失消息。

第三种方式麻烦，要修改class服务接口的逻辑，动作较大，后期有时间再修改。

修改hystrix和ribbon的超时时间来解决问题

之前关于hystrix、ribbon、feign介绍的文章里说到过这三个组件之间的时间配置关系如下：

feign和ribbon配置关系：如果不启用Hystrix，Feign的超时时间则是Ribbon的超时时间，Feign自身的配置也会被覆盖

ribbon和hysrix的配置关系：

hystrix设置的超时时间必须大于等于ribbon的超时时间，否则会报错如下:

2019-10-12 21:56:20,208   111231 [http-nio-8084-exec-2] WARN    o.s.c.n.z.f.r.s.AbstractRibbonCommand - The Hystrix timeout of 10000ms   for the command operation is set lower than the combination of the Ribbon   read and connect timeout, 24000ms.

因为ribbon多次重试都是在一个hytrix中的所以配置公式如下：

Hystrix的超时时间 >= Ribbon的重试次数(包含首次) * (ribbon.ReadTimeout + ribbon.ConnectTimeout)
Ribbon重试次数(包含首次)= 1 + ribbon.MaxAutoRetries  +  ribbon.MaxAutoRetriesNextServer  +  (ribbon.MaxAutoRetries * ribbon.MaxAutoRetriesNextServer)

因为class接口服务设置了Thread.sleep(10000)也就是10s，再根据上面的配置规则，设置ribbon超时时间=12s，hystrix超时时间=15s进行测试。

修改mq配置如下：

ribbon:
  #说明：使用Apache HttpClient连接超时时间，默认3000 单位为毫秒
  ConnectTimeout: 3000
  #说明：使用Apache HttpClient读取的超时时间，默认3000 单位为毫秒
  # 改为10s中
  ReadTimeout: 12000
hystrix:
  command:
    default:
      execution:
        isolation:
          thread:
          	# 执行超时时间，默认为1000毫秒
          	timeoutInMilliseconds: 15000