lostash Timeout executing grok 问题排查

最新推荐文章于 2023-04-08 18:07:08 发布

夜月行者

最新推荐文章于 2023-04-08 18:07:08 发布

阅读量2.5k

点赞数

分类专栏： # 使用经验文章标签： elasticsearch logstash ELK

本文链接：https://blog.csdn.net/u013200380/article/details/121606987

版权

使用经验专栏收录该内容

17 篇文章 0 订阅

订阅专栏

文章目录

Timeout executing grok 问题排查

Timeout executing grok 问题排查

使用logstash的时候发现会有这个报错，导致logstash不稳定，input端是kafka，就会导致kafka的反复rebalance,一开始排查思路有问题，而且网上的资料可能都是其中的一个原因，所以导致我的排查思路偏了。

1. 问题背景

我有一组logstash 从kafka中消费日志数据，解析后丢到ES当中，提供一些日志的检索能力。大概的配置是这样的。

1. 基础配置

logstash版本 7.5.0

jvm

java -version
openjdk version "1.8.0_312"
OpenJDK Runtime Environment (build 1.8.0_312-b07)
OpenJDK 64-Bit Server VM (build 25.312-b07, mixed mode)

```
-Xms6g
-Xmx6g
```

config/logstash.yml

pipeline.workers: 6
pipeline.batch.size: 50

2. pipeline配置

input {

  kafka{

        bootstrap_servers => "xxx:9092"
        topics_pattern => "log_.*"
        auto_offset_reset => "latest"
        group_id => "log-es-find"
        consumer_threads => 1
        client_id => "node123"
        partition_assignment_strategy  => "org.apache.kafka.clients.consumer.RoundRobinAssignor"
        max_poll_interval_ms => "600000"
        max_poll_records => "100"

  codec => json {
          charset => "UTF-8"
      }
  }

}





filter {

    mutate {
        remove_field => [ "host","@timestamp" ]
      }

    if "_LOGV3_" not in  [message] {
          grok {
              match => { 
                  "message" => '^%{LOGLEVEL:log_level} %{TIMESTAMP_ISO8601:time} %{HOST:host_name} %{SERVICCE:service_type} %{STRING:process} %{STRING:thread} - %{SESSION_ID:session_id} %{GREEDYDATA:message_log}$' 
              }
              remove_field => ["message"]
          }

    } else {

          grok {
                match => { "message" => '^%{LOGLEVEL:log_level} %{TIMESTAMP_ISO8601:time} %{HOST:host_name} %{SERVICCE:service_type} %{STRING:process} %{STRING:thread} _LOGV3_ %{SESSION_ID:session_id} %{EVENT_MARK:event} %{GREEDYDATA:message_log}$' 
                }

          }

          json {

              source => "message_log"
              target => "doc.custom"
              remove_field => ["message","message_log"]

          }

          mutate {
                rename => { "doc.custom" => "doc.%{event}" }
          }

    }

   if "_groktimeout" in [tags] {

      grok {

         match => {"message" => "^%{LOGLEVEL:log_level} %{TIMESTAMP_ISO8601:time} %{HOST:host_name} %{SERVICCE:service_type}"}
         remove_tag => [ "_groktimeout" ]
         add_tag => [ "timeout" ]
      }
  }

  if "_grokparsefailure" in [tags] {

      grok {
          remove_tag => [ "_grokparsefailure" ]
          add_tag => [ "grok_failure" ]
          match => { "message" => '^%{LOGLEVEL:log_level} %{TIMESTAMP_ISO8601:time} %{HOST:host_name} %{SERVICCE:service_type} %{GREEDYDATA:message_log}$' }
      }
   }

  date {
        match => ["time",  "ISO8601"]
        target => "@timestamp"
        locale => "cn"
  }


  mutate {
          remove_field => ["time", "@metadata","host","input", "agent","ecs","log" ]
  }

  if "_grokparsefailure" in [tags] {

      mutate {
          add_field => {
            "service_type" => "grok_failure"
          }
      }
   }

   if "_groktimeout" in [tags] {
        mutate {
              add_field => {
                  "service_type" => "grok_time_out"
              }
        }
   }

}



output {

 elasticsearch {

    hosts => ["http://es:9200"]
    index => "mai_log_%{[service_type]}_detail_%{+YYYY.MM.dd}"
    user => "elastic"
    password => "xxx"

  }
}

2. 问题表现

因为之前搞过这一套，所以就很熟练的搭建起来了，logstash也没有做太多的配置，重点是没有对gc日志进行配置，没有打印gc日志，影响了后面的判断。

logstash启动后表现异常，只是数据中有的数据的json字段是可以无限拓展的，导致ES中的有些索引有问题，后来把对应的一些字段修改为flattened解决了相关问题。但是logstash还有一个问题就是运行个7，8个小时就开始不稳定，频繁的与kafka失去联系，导致频繁发生rebalance。查看日志，发现有下面这样的日志：

[2021-11-25T11:22:57,107][WARN ][logstash.filters.grok    ][main] Timeout executing grok '%{LOGLEVEL:log_level} %{TIMESTAMP_ISO8601:time} %{HOST:host_name} %{SERVICCE:service_type} %{STRING:process} %{STRING:thread} - %{SESSION_ID:session_id} %{GREEDYDATA:message_log}$' against field 'message' with value 'Value too large to output (3876 bytes)! First 255 chars are: debug 2021-11-25T11:01:35.303029+08:00 kvm-jobs-job-index-online3 go_recall_job 30343 30349 - 10e11e80e227f6053f1637809295e246 uid=187853021, user={"Uid":187853021,"ExpectPosition":"跨境运营","LikeWords":[{"Term":"运营","Weight":0.62232894},{"Term":"跨境","Weight"'!

频繁的rebalance导致logstash几乎无法工作

3. 尝试通过修改 memory-queue+ poll-size

这个时候想着有可能是某些字段的grok太复杂导致了logstash在处理数据的时候超时了？拿着Timeout executing grok作为关键字搜索了一波，大部分也是说grok使用的pattern太复杂了，于是年少无知的我又开始优化pattern（其实我的pattern并不复杂）。同时学习了一下logstash的消费模型。logstash的input和(filter+output)是分开的，input只是负责数据拉取，放到内存的缓存队列memory-queue中，filter从memory-queue中取数据消费。memory-queue是有大小限制的，当filter+output比较慢的话就会阻塞input的操作，这个时候我想会不会因为每次从kafka pull的数据太多导致呢？poll的数据太多，filter消费不动，导致input等待太久导致了kafka的超时。当时想着Timeout executing grok是因为少量比较特殊的数据导致的，这种情况也符合偶先的情况。

于是上面的一些配置做了改动

pipeline.workers: 6
pipeline.batch.size: 50

max_poll_interval_ms => "600000"
max_poll_records => "100"

这个实际上是改动后的配置，之前用的是默认的，比这个大。

再次重启了logstash，心想这次应该没有啥问题了吧，结果运行了一天左右，还是出现了上面的问题，黔驴技穷了，想了想，只能试试分析一下gc日志了，于是又开启了gc日志。

4. 通过gc日志定位问题

开启gc

jvm.options


## GC logging
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintClassHistogram
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime

# log GC status to a file with time stamps
# ensure the directory exists
-Xloggc:./gc_logs/gc.log

再次重启，等问题再次复现的时候观察gc日志 , 发现有频繁的full-gc操作，以至于logstash无法进行工作了，因为几乎所有的时间都在进行full-gc, 但是full-gc之后内存没有下降，很明显，发生了内存泄露，应该是logstash的啥bug让我触发了

2021-11-27T17:36:21.048+0800: 78068.514: [CMS-concurrent-mark-start]
2021-11-27T17:36:23.878+0800: 78071.344: [Full GC (Allocation Failure) 2021-11-27T17:36:23.878+0800: 78071.344: [CMS2021-11-27T17:36:25.512+0800: 78072.978: [CMS-concurrent-mark: 4.462/4.464 secs] [Times: user=39.30 sys=0.82, real=4.47 secs]
 (concurrent mode failure): 4194303K->4194303K(4194304K), 35.7906436 secs] 6081790K->4204353K(6081792K), [Metaspace: 103267K->103267K(1155072K)], 35.7908146 secs] [Times: user=44.59 sys=0.67, real=35.79 secs]
2021-11-27T17:36:59.669+0800: 78107.135: Total time for which application threads were stopped: 35.7917723 seconds, Stopping threads took: 0.0000556 seconds
2021-11-27T17:36:59.673+0800: 78107.139: Total time for which application threads were stopped: 0.0027825 seconds, Stopping threads took: 0.0001835 seconds
2021-11-27T17:37:00.674+0800: 78108.140: Total time for which application threads were stopped: 0.0007674 seconds, Stopping threads took: 0.0000516 seconds
2021-11-27T17:37:01.669+0800: 78109.135: [GC (CMS Initial Mark) [1 CMS-initial-mark: 4194303K(4194304K)] 4310321K(6081792K), 0.0121234 secs] [Times: user=0.10 sys=0.00, real=0.02 secs]
2021-11-27T17:37:01.681+0800: 78109.147: Total time for which application threads were stopped: 0.0129999 seconds, Stopping threads took: 0.0000897 seconds
2021-11-27T17:37:01.681+0800: 78109.147: [CMS-concurrent-mark-start]
2021-11-27T17:37:06.359+0800: 78113.825: [CMS-concurrent-mark: 4.678/4.678 secs] [Times: user=43.90 sys=1.14, real=4.67 secs]
2021-11-27T17:37:06.359+0800: 78113.825: [CMS-concurrent-preclean-start]
2021-11-27T17:37:06.569+0800: 78114.035: [Full GC (Allocation Failure) 2021-11-27T17:37:06.569+0800: 78114.035: [CMS2021-11-27T17:37:12.639+0800: 78120.106: [CMS-concurrent-preclean: 6.278/6.280 secs] [Times: user=7.09 sys=0.17, real=6.28 secs]
 (concurrent mode failure): 4194303K->4194303K(4194304K), 40.9531845 secs] 6081787K->4205126K(6081792K), [Metaspace: 103268K->103268K(1155072K)], 40.9533777 secs] [Times: user=39.95 sys=0.84, real=40.96 secs]
2021-11-27T17:37:47.523+0800: 78154.989: Total time for which application threads were stopped: 40.9546434 seconds, Stopping threads took: 0.0000614 seconds

使用jamp看了一下内存分布

jmap -histo:live $pid

num     #instances         #bytes  class name
----------------------------------------------
   1:      17289297      691571880  org.jruby.util.ByteList
   2:      17245027      689801080  org.jruby.RubyString
   3:      17417048      659620560  [C
   4:      17334568      554706176  java.util.concurrent.ConcurrentHashMap$Node
   5:      17214558      550865856  org.logstash.FieldReference
   6:      17296590      514218192  [B
   7:      17416092      417986208  java.lang.String
   8:          8271      135421720  [Ljava.util.concurrent.ConcurrentHashMap$Node;
   9:        139671        4469472  java.util.HashMap$Node
  10:         74368        4338232  [Ljava.lang.Object;

看起来不对劲儿，然后再社区发了一个discuss,果然是logstash的一个bug，遗憾的是这个bug已经有人提交commit了，但是还没有修复。。。
触发这个bug的原因是我的json 里面有一些字段搞的不规范，导致所有的日志中json的key的总合是上亿的，所以发生了内存泄露。是json filter的一个bug。

回顾这个问题，最开始的时候，一直以为是自己使用有问题，所以也就没有去打印gc，加上依赖自己之前的经验，感觉ELK应该bug比较少，真的没有想到，绕了一大圈，栽跟头了。。。

夜月行者

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
lostash Timeout executing grok 问题排查

Timeout executing grok 问题排查使用logstash的时候发现会有这个报错，导致logstash不稳定，input端是kafka，就会导致kafka的反复rebalance,一开始排查思路有问题，而且网上的资料可能都是其中的一个原因，所以导致我的排查思路偏了。1. 问题背景我有一组logstash 从kafka中消费日志数据，解析后丢到ES当中，提供一些日志的检索能力。大概的配置是这样的。1. 基础配置logstash版本 7.5.0jvmjava -ver
复制链接

扫一扫

专栏目录