基于TBDS的flume异常问题排查过程

版权声明：本文由王亮原创文章，转载请注明出处: 
文章原文链接：https://www.qcloud.com/community/article/214

来源：腾云阁 https://www.qcloud.com/community

 

现象

长期运营中发现部署了flume集群的磁盘满，经过排查发现flume的日志目录导致。

具体问题

具体看flume的大文件日志发现，某个MySQL相关的sink持续抛出异常，打印了大量的日志

分析过程

根据这个异常信息（exception）即：
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed
字面意思为MySQL服务的状态（连接）已经关闭的状态下，仍然有提交事务操作，抛出了异常，但这个异常持续抛出，仍需要深入分析。

配置分析

既然是flume抛出的，且与MySQL有关，那缩小问题范围，查找flume里谁在写MySQL。（flume的配置一般位于/etc/flume/conf/agent/flume.conf）

根据配置中唯一一条与MySQL相关的配置逻辑：读取HiveServer的日志，过滤其中的SQL语句（以Metadata collec*过滤），结果存入到sink里配置的MySQL数据表hive_run_sqlinfo。

flumeagent逻辑分析

以上sink里调用了一个com.tencent.tbds.flume.sink.MysqlSinkForMetadata的类，这是一个自定义类，我们在引用路径里找到这个类所在jar并反编译之（decompiler），基本逻辑与注释如下：

Sink初始化阶段

Sink循环执行阶段

Sink关闭阶段

关闭阶段仅仅检查连接是否存在。

可能的原因

从sink的逻辑看，只有在空连接的情况下，sink状态才会是BACKOFF，其他情况下状态都是READY，且在向MySQL提交事务前后，不会检查连接状态，即使在SQL抛出异常的情况下也没有修改sink状态，导致提交抛出异常后，sink循环执行，循环抛出异常。这里就是不断抛出异常的根本。那么连接到底是什么时候关闭的呢？这里的原因猜测有2个：(1)sink长时间与MySQL没有交互，超过连接自动关闭时间；(2)MySQL的异常关闭。

问题确认

是否sink长时间与MySQL无交互
查询MySQL的超时配置如下：

配置为默认配置28800秒即8小时。
查看HiveServer的日志，统计每小时执行SQL的数量如下：

可见，sink与MySQL之间的断开并非二者长期无交互。

是否人为断开服务
查询人为启动MySQL的时间如下：

flume的异常时间如下：（从异常提交的事务本身内容的时间看）：

时间吻合。

结论
MySQL服务异常导致flume提交事务时连接中断，且flume没有处理这种异常，引发死循环提交事务，并在这种异常情况下，flume已无法正常工作。

问题重现

根据以上的推论，可进行如下验证这个异常：

HiveServer产生日志

在HUE里执行多次HiveSQL

手动强制关闭MySQL

手动重启flume写入的MySQL实例。

查看flume表现

flume进入无限循环的抛出异常状态，验证成功。

总结

这里的主要原因是MySQL服务异常导致产生的连锁反应。权宜之计可以在sink的代码中提交事务出异常时，修改下sink的状态为BACK.OFF，防止不断打印日志造成机器磁盘满影响其他服务（待验证）。