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

Java 同时被 2 个专栏收录
9 篇文章 0 订阅
1 篇文章 0 订阅

问题描述

错误记录如下

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

idstart_timeend_timetime
777844732021-07-13 11:22:292021-07-13 11:37:30901
777844742021-07-13 11:22:292021-07-13 11:37:30901
777844752021-07-13 11:22:292021-07-13 11:37:30901

问题分析

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

用户断开连接disconnect,并发送消息给rabbitMQ
mq-consumer服务获取消息进行处理
调用class服务处理
处理数据,并插入观看记录
是,则进行重试,最多重试3次
websocket
rabbitMQ
mq-consumer消费服务
class服务
是否发生错误?
结束

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

  1. websocket断开时重复发送消息至rabbitMQ队队列
  2. 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超时,然后进行测试。

测试结果如下 :

idstart_timeend_timetime
771694092021-07-15 13:51:002021-07-15 13:51:4847
771694102021-07-15 13:51:002021-07-15 13:51:4847
771694112021-07-15 13:51:002021-07-15 13:51:4847
771694122021-07-15 13:51:002021-07-15 13:51:4847
771694132021-07-15 13:51:002021-07-15 13:51:4847
771694142021-07-15 13:51:002021-07-15 13:51:4847

数据插入了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

测试结果如下:

idstart_timeend_timetime
771694152021-07-15 16:25:442021-07-15 16:26:1228
771694162021-07-15 16:25:442021-07-15 16:26:1228
771694172021-07-15 16:25:442021-07-15 16:26:1228
771694182021-07-15 16:25:442021-07-15 16:26:1228

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

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

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

详细问题描述

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

解决方法

目前想到的解决方案:

  1. 增加mq-consumer服务的ribbon和hystrix的超时时间,保证class服务接口在超时时间内已经返回结果
  2. 在mq-consumer服务中去掉自己写的消息重试机制
  3. 修改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

测试结果如下:

idstart_timeend_timetime
771694242021-07-16 08:10:582021-07-16 08:11:3637

链路调用如下,tranceId=3c68b6190767afd9:
在这里插入图片描述hystrix中只有一次post请求且没有超时中断,数据结果也正常。

总结

mq-consumer服务使用了默认的ribbon超时时间,但是class服务处理时间较长导致mq-consumer中断并重试,最终导致class服务被多次调用插入了重复的数据。
所以生产配置提高一下ribbon和hytrix的超时时间即可。

  • 0
    点赞
  • 0
    评论
  • 0
    收藏
  • 一键三连
    一键三连
  • 扫一扫,分享海报

©️2021 CSDN 皮肤主题: 数字20 设计师:CSDN官方博客 返回首页
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值