ES重复日志线上问题排查经历

一、现象：ES中出现重复日志，具体表现如下：

二、调查背景：

       由于目前日志采集的整体流程如下：应用log4j2(flumeClient) → flume-collector(kafka-producer)  → kafka → logstash(kafka-consumer) → ES

       由于这一流程的存在，在红色标识的前半段流程，本次文章中暂不做分析。（尽管可能会有多种其他原因导致kafka重复生产消息）。下面的分析主要针对蓝色标识的后半段流程进行分析。

三、kafka → logstash(kafka-consumer) → ES 重复日志原因分析

1、首先我们稍微具体化这个流程：

       这个流程其实在logstash的配置文件中已经有体现，它通过kaka-input插件、filter插件、output插件共同协作，完成了日志从kafka到ES写入的完整流程（由于Logstash使用的是Jruby开发的，其中的细节可能只有从源码中去获取真相了）。logstash简单的配置示例如下：

input {
        kafka {
                group_id => "logstash-test-multi-cluster"
                bootstrap_servers => "172.17.0.23:4100"
                topics => "huoli_sys_log_test"
                codec => "json"
        }
}

filter {
  if [type] == "nginxacclog" {

         mutate {
                 remove_field => ["slbip","kafka","domain","serverip","url","@version","offset","input_type","count","source","fields","beat.hostname","host","tags"]
         }
        }

}

output {
        elasticsearch {
            hosts => ["172.17.0.28:9200", "172.17.0.28:9201", "172.17.0.28:9202"]
            index => "logstash-test-log-%{dptCode}-%{bizCode}-%{+YYYY.MM.dd}"
            manage_template => true
            user => logstash
            password => huoli_estest
        }
}

2、现在把logstash的处理流程整理成如下图一：kafka → logstash(kafka-consumer) → ES 流程图 所示。

根据kafka机制和logstash的配置，具体化的流程就是：

     a）、logstash读取配置文件中的kafka-input配置，完成consumer的初始化，初始化完成后会生成两个重要的组件：心跳组件、offset自动提交组件。它们会在后台跟kafka的broke的groupCoordinator进行交互。它们作用已经在图中标示出来了。

     b)  、消费初始化完成之后，后开始执行poll()操作从kafka-broker中轮询消息，再通过logstash-filter插件过滤，最后在通过logstash-output插件，写入ES。

3、了解了logstash的基本工作原理，现在我们带着问题去理解这个流程：ES中为什么会有重复日志（各种信息一模一样）。

    3.1、直接原因肯定是logstsah在output插件中多次执行写操作。那么什么情况下会导致它多次write呢？可能原因如下：

        a)、logstash自带重试机制，output插件自己进行业务逻辑的重试。

        b)、logstash重复消费kafka，导致同一个log被消费多次后output到ES，从而导致ES日志重复。

       以上a和b两种可能是导致日志重复的直接原因，但是从网上的各种资料来看，貌似a原因的可能性比较小，网上也没搜到关于logstash自带重试功能的资料。（logstash的插件是基于ruby开发的，要确认这个问题，可能只能去撸ruby脚本了）。当数据规模较大时，b）情况导致重复的可能性较         大，所以后续我们的分析都基于这种原因来分析。

     3.2、这里分析到，重复写日志是由于kafka重复消费导致的，那么什么情况又会导致logstash(kafka消费者)重复消费呢？直接原因是，消费者消费到了错误offset,这个offset 可能是上次消费（某个消费者）未来得及提交的offset（位置重塑）。如上图一所示：卷轴形状 Q3 问题 （offset为什么会不一致？）由于kafka消费的时候默认是自动提交offset,并且每个5s自动提交一次最新的offset位置。问题来了：如果在这给自动提交间隔期间，kafka消费者组中某个消费异常，恰好这个异常出现在这个auto.commit.interval.ms（5s）间隔中间，导致本次拉取消费的kafka-log (日志) 的offset没法提交，但是logstash这个时候已经处理了其中的某一部分log(日志)并写入了ES。详细过程见下图二：

           图二：logstash消费者消息poll/rebalance/offset 所示：

      3.3、图一：Q3答案在图二中得到解答、上图也已经一并画出了重复消费offset的原因，那就是rebalance导致消费者被重新分配，新的消费者（logstash-cosumerD）读取了上一 个消费者（logstash-cosumerA）未提交的offset,并开始消费数据。显然这会导致1-3之间的log被重复处理。

      3.4、经过上述分析，得知logstash-comsumer异常退出group --导致--> rebalance --导致--> 未提交的offset被重复消费 --导致--> 日志重复。

              那么问题来了：什么情况会导致logstash-comsumer异常或者自动退出group呢？

              看图一里面，两个重要的参数：

                   1)、session.timeout.ms默认10s: 请参考图一：tips1 的描述。

                   2)、max.poll.interval.ms默认300s：请参考图一：tips2 的描述。

             由于session.timeout.ms这个参数是心跳逻辑相关的，而消费者心跳是单独的线程来维护的，它出现超时的可能性比较小，除非JVM的fgc比较严重，导致心跳线程无法抢夺到到cpu时间分片，从而导致心跳超时。这个理论上应该通过监控logstash的JVM的GC和它本身的异常日志来来验                   证(图一：Q4的答案之一) 。

            那么剩下的就是max.poll.interval.ms这个参数了，它又是如何影响logstash-consumer的呢？

            这个时候，我们带着图一：Q1 和 Q2 的疑问来分析这个场景。 Q1：logstash的处理流程跟poll()方方法是否是线程同步的？这个应该是整个问题分析的关键点（logstash的插件是基于ruby开发的，要确认这个问题，可能只能再去撸ruby脚本了），从网络上查询的资料和线上环境问题可以初 步推断，这个处理流程是同步进行。Q1。假设它异步处理，kafka堆积可能不会太严重，并且当日志量大的时候，logstash异步处理kafka消息，它必须在内存里面缓存消息，这最终必然会导致logstash的JVM频繁的FUllGC,因为从线上环境来看，消费速度是远远低于生产速度的，这必然会导致JVM内存爆掉。但是线上的logstash貌似还比较健康。所有可以从侧面证实同步处理这个推断的正确性。 在同步处理的情况下：logstash机会等每次拉取的一批log全部写入ES后在进行下一次的poll()操作，最终两次poll()的时间间隔就取决于，logstash处理一批log写入ES的时间了，而写ES又是一次次的网络IO，最终的瓶颈就落到了ES的output操作。如图一：tips:2 所述，消息业务处理（写ES）如果时间过长，会导致consumer退出consumer group从而触发rebalance。到这里Q2也得到解答。

        3.5、最终我们的结论是：当output由于某种原因阻塞（ES集群写入过慢最直接的原因），导致kafka消费者触发rebalance，从而导致重复消费，产生重复日志。

4、当然，导致rebalance的原因还有很多，这里从最关键和最有可能的点来解读了重复消费导致重复日志的根本原因。

       要验证上述推断：需要在线上环境持续做如下操作：

        1、观察logstash异常日志，看看是否有re-joining group、 auto offset commit failed的关键字。

        2、观察kafka-topic分区的堆积情况。

        3、观察ES的健康状况，当ES集群异常（节点挂掉，索引段合并导致IO大而阻塞写入）

        4、网络稳定情况。

5、由于ES集群性能问题导致重复日志的嫌疑最大，所以得从改善ES集群IO性能入手。有对ES调优了解的欢迎持续补充文档，一起证实和解决线上的问题。