记一次 Python 代码中容错 bug 导致 Kafka 消息数量异常翻倍的 debug 经历

0x00.前言

看到云 + 社区发布了「热点技术征文赛第二期」征文活动，决定参与【编程语言】选题赛道，本文属于【项目实战经验分享】

主要给大家介绍最近一次 Kafka 消息异常翻倍的 debug 流程

0x01.场景

项目中使用到了 Kafka 中间件，数据流转图如下，主要分为 3 个过程

简单介绍一下

1. Telagraf 将数据生产至 _rawdata topic 中

2. rawdata consumer 从 _rawdata topic 中拉取数据，处理判断数据类型，再次生产至 _policy 或 _flow 的 topic 中

3. consumer 从 _policy 或 _flow 的 topic 中拉取数据，进行处理，最终入库

图中黄色部分的 consumer 是基于 Python 写的消费者，包含 rawdata consumer 和 consumer

0x02.异常翻倍

而自己在做的是性能测试，因此搭建了 Prometheus + Grafana + kafka_exporter 业界公认的监控系统

通过 kafka_exporter 可以清楚的看到 Kafka 生产和消费的各种指标

• Message in per second：每秒入消息数量
• Lag by Consumer Group：消费者组的 LAG
• Message in per minute：每分钟入消息数量
• Message consume per minute：每分钟消费消息数量

并且可以通过时间的形式查看，RT

在测试中逐渐施压，Kafka 消息越来越多，而配置的 rotation 时长为 3h 较长，最终导致硬盘空间 full

因为硬盘满了之后，终端实在是太卡了，等了很久都没有响应，决定直接重启！

重启之后查看生产速率（200/min）发现是重启之前（400/min）的一半？

然后无任何操作一段时间（半小时左右）后，生产速率又上升至重启前的（400/min），非常奇怪

想了想，再试一次。但是这次不重启整个虚拟机，只重启全部的微服务

重启后生产速率又降回一半（200/min）了

继续等待（半小时左右），果然生产速率又上升至重启前的（400/min）

那么问题来了

1. 正确的生产速率应该是 200/min 还是 400/min？
2. 是什么原因导致在无任何操作得情况下，消息异常翻倍？

0x03. 寻找 bug

既然是消息异常翻倍，简单粗暴一点儿的话，修改代码将所有消息打印到日志中

对比一下翻倍前后消息的具体内容不就知道了嘛。RT，翻倍前 320 条，翻倍后 642 条

发现翻倍时相同的数据有两份，对比这两份内容，结果完全一致！

也就是说翻倍的数据是因为重复生产了！

因为 Procuder 是基于 Python 写的，那么是时候 Review 代码了，全局搜索 .produce 方法，很快就找到了根源所在

小小的一个 kafka_producer 函数中，有很多存在问题的地方

不难看出这里首先这里用 try except 包裹了 BufferError，先不管这个 BufferError 是什么，触发一次 messages_to_retry 就加一，然后重试。重试代码中，继续第 2 次生产，如果又产生 BufferError 就再二次重试第 3 次生产

1. messages_to_retry 没有重置为 0。也就是说只要有一次 BufferError，自此开始，后续全部消息都要重试一次，这就解释了为什么运行一段时间之后，消息数量翻倍。同时也可以得出，翻倍前的消息数量才是真正的数量

2. 先抛开 except BufferError as e 中 e 变量未被使用不谈，这个 BufferError 是怎么产生的。继续修改代码 traceback 看一下

确实是生产中会产生的报错，BufferError: Local: Queue full

但是奇怪的地方是，每次运行微服务，只会产生这一次报错，导致消息数量 x2。测试过程中，没有遇到产生两次报错，导致消息数量 x3 的情形

3. 重试机制写的不好，重试机制中的二次重试第 3 次生产如果失败了，那就真失败了，没有被 try except 包裹，不会继续重试了

0x04. debug

因为自己发现 Telegraf 可以实现 rawdata consumer 逻辑（这部分内容后续有时间还会介绍给大家），也就是用不到基于 Python 写的生产者了，这部分代码全部木大

从根本上解决 bug：没有代码，就没有 bug（把代码全给扬了，笑

0x05. 后记

这次 debug 流程耗时较长，有一部分原因是因为将翻倍的数量误认为是正常的数量级，一直在寻找丢数据的原因

万万没有想到，这翻倍的数量才是不正常的情形。意识到这一点后，在代码中一步一步的打印日志，最终定位到 bug 所在

思路供大家参考，可惜项目中没有引入类似 Sentry 一样的错误上报系统，只能在代码中一步一步的打印日志了