Fluentd 缓冲区写满排查 & 优化

k8s集群无法创建pod，经过排查后是由于Fluentd配置不当，造成磁盘被写满，撰文记录一下解决问题的过程。

一、问题简述

今早有同事反馈无法在k8s集群上新建pod，报错信息Failed to create pod sandbox : mkdir /var/log/pods/xxxxxx : no space left on device。

登上物理机一看，是/var/log文件夹存储空间满了。进入文件夹后发现是fluentd-buffers占用了4G的空间。

二、问题排查

第一感觉是Fluentd设置的kafka缓冲区大小不够了，准备把kafka缓冲区移出/var/log这个路径，放到其他地方去。

但是感觉很奇怪，因为之前做过压测，Fluentd的流程是数据过滤&处理&加工，然后推送到Kafka。整体流程的QPS在6000条左右，对应推送到Kafka的文件大小在8M左右/S。同时系统的瓶颈在于数据过滤&处理&加工部分，数据推送模块还远远没有达到瓶颈。

同时在压测的时候每秒打印大约1W条左右日志，Fluentd也没有挂，只是处理&推送的速度赶不上日志生产的速度，会有延迟。所以不应该出现Kafka缓冲区的累积的情况。

通过Kuboard查看这台机器上的Fluentd的log，发现在报错，缓冲区的数据没有丝毫的减少。

2021-12-15 02:48:47 +0000 [warn]: #0 [kafka] failed to flush the buffer. retry_times=3360 next_retry_time=2021-12-15 02:49:21 +0000 chunk="xxxxxxxxxxxxxxxxxxxx" error_class=Kafka::MessageSizeTooLarge error="Kafka::MessageSizeTooLarg

看到报错大概就明白缓冲区被写满的原因了，因为无法推送数据到kafka，导致数据会越写越多，直到缓冲区写满。

三、问题定位

这个时候怀疑应该是某些job打印的日志太长，导致推送到Kafka报错。当时第一反应是什么日志会这么长，因为我印象里之前测试过Java Exception发送到Kafka，非常长，大概有100行，都是可以正常发送的。但是作为服务要保证稳定性和兼容性，所以超长日志这种情况是需要适配的。

于是查询了一下，fluentd-plugin-kafka有max_send_limit_bytes参数可以控制发送数据的最大长度。于是在Fluentd配置文件添加好后，在Kuboard执行新的yaml文件，然后重启Fluentd。

重启后查看该机器的Fluentd log能看到有大量的日志超过长度被舍弃，然后打印出来。看到日志感觉不太对劲，看样子是某个job在打印一些参数一样的东西，然后在重复打印。类似于下面的数据格式：

{
    "log":"2021/12/15 19:57:02[INFO]-[com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:991)]: XXXXXXXXX",
    "sites1": [
        { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
        { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
    ],
    "sites2": [
        { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
        { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
    ],
    "sites3": [
        { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
       	{ "name":"菜鸟教程" , "url":"www.runoob.com" }, 
        { "name":"google" , "url":"www.google.com" }, 
        { "name":"微博" , "url":"www.weibo.com" },
    ]
}

通过日志里面的部分pod数据就可以定位到具体的job了，然后查看那个job的log情况，发现log中是一部分一部分打印的：

2021/12/15 19:57:02[INFO]-[com.alibaba.druid.pool.DruidDataSource.init(DruidDataSource.java:991)]: XXXXXXXXX 

"sites1": [
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
 ]

"sites2": [
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
 ]

"sites3": [
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
  { "name":"菜鸟教程" , "url":"www.runoob.com" }, 
  { "name":"google" , "url":"www.google.com" }, 
  { "name":"微博" , "url":"www.weibo.com" },
 ]

也就是说job的日志打印是没问题的，但是却被Fluentd合并成了一条超长的日志。

这个时候我想到了配置的concat模块，会通过正则匹配去把多条日志合并成一条，上方刚好符合这个场景。

四、问题修复

整个问题的思路就很清楚了，job反复打印一些类似于配置文件一样的日志，同时偶尔打印正常的Java日志。造成出现一个带时间戳的日志+多个不带时间戳的日志，合并成一个超长的日志。然后推送到Kafka报错，导致日志堆积，缓冲区越来越大，最终打满整个物理机的/var/log目录，影响k8s集群服务。

所以这个问题要从三个方面去修复：

1、减少concat模块等待时间

由于concat模块是用来合并正常的Exception和一些配置文件，所以是需要保留的。像本文描述的异常情况是比较少见的，concat模块原理是通过正则匹配时间戳来合并日志，如果一直没等到下一个符合正则条件的时间戳，则等待设置时间然后走超时逻辑，所以可以让等待时间尽可能少。因为正常Exception是瞬间就全部打出来，需要合并的配置等信息出现的时间也不会太长。

所以将flush_interval从10s修改为1s。