lostash Timeout executing grok 问题排查
文章目录
- Timeout executing grok 问题排查
- 1. 问题背景
- 1. 基础配置
- 2. pipeline配置
- 2. 问题表现
- 3. 尝试通过修改 memory-queue+ poll-size
- 4. 通过gc日志定位问题
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 => 1client_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: 50max_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.ByteList2: 17245027 689801080 org.jruby.RubyString3: 17417048 659620560 [C4: 17334568 554706176 java.util.concurrent.ConcurrentHashMap$Node5: 17214558 550865856 org.logstash.FieldReference6: 17296590 514218192 [B7: 17416092 417986208 java.lang.String8: 8271 135421720 [Ljava.util.concurrent.ConcurrentHashMap$Node;9: 139671 4469472 java.util.HashMap$Node10: 74368 4338232 [Ljava.lang.Object;
看起来不对劲儿，然后再社区发了一个discuss,果然是logstash的一个bug，遗憾的是这个bug已经有人提交commit了，但是还没有修复。。。
触发这个bug的原因是我的json 里面有一些字段搞的不规范，导致所有的日志中json的key的总合是上亿的，所以发生了内存泄露。是json filter的一个bug。
回顾这个问题，最开始的时候，一直以为是自己使用有问题，所以也就没有去打印gc，加上依赖自己之前的经验，感觉ELK应该bug比较少，真的没有想到，绕了一大圈，栽跟头了。。。
lostash Timeout executing grok 问题排查相关推荐
- python中timeout什么意思_关于timeout的一次排查（上）
最近总有用户反馈说Redash下载比较大的Excel就会出现"失败 - 服务器出现问题",而且每次从点了下载到出现错误提示时间都是差不多的.我先查看了Nginx的error日志,显 ...
- （六十五）Android O StartService的 anr timeout 流程分析
前言:之前在(六十四)Android O Service启动流程梳理--startService 梳理了startService的一般流程,anr的没有涉及,本篇就以anr的为关注点梳理下流程. 参考 ...
- Android 开发总结大全
*android 开发总结 框架,工具,流程 业余时间总结学习 代码框架总结 1. 可以将activity中基类保存每一个子类的Context,然后通过Application中的函数负责保存,任意时候 ...
- Android 进阶——Framework 核心ANR（ Applicatipon No Response）机制设计思想详解
文章大纲 引言 一.一些与ANR有关的计算机理论 1.互斥锁(Mutexes)概述 2.死锁(Deadlocks )概述 二.ANR 设计目的概述 三.Android 组件ANR超时机制 1.Acti ...
- Android-ANR
一. ANR概述 什么是ANR ANR,是"Application Not Responding"的缩写,即"应用程序无响应".在Android中,如果应用程序 ...
- 如何处理Dubbo调用超时
一.简述 同步调用是一种阻塞式的调用方式,即 Consumer 端代码一直阻塞等待,直到 Provider 端返回为止.dubbo默认的协议是netty, Netty 是 NIO 异步通讯机制,那么服 ...
- Android进阶知识：ANR的定位与解决
1.前言 ANR对于Android开发者来说一定不会陌生,从刚开始学习Android时的一不注意就ANR,到后来知道主线程不能进行耗时操作注意到这点后,程序出现ANR的情况就大大减少了,甚至于消失了. ...
- 时延敏感业务低概率超时问题分析
前言 作为阿里云底层提供的基础设施,内部的物理网络和许多网络产品在数据平面给客户的可操作性并不高,从一定程度上来说是个黑盒.当然,在传统的IDC环境,业务和物理网络之间也存在同样的隔阂.所以在遇到业务 ...
- Android 系统（135）---Android anr 分析步骤总结
Android anr 分析步骤总结 前言:最近经手了比较多的anr问题,声明经手不是解决,只是从log上推断造成anr的原因,以此作为根据转交给对应的人来处理. 1. ANR简介 ANR全名Appl ...
最新文章
- Win10控制桌面图标显示
- Qt/PyQt中使用系统全局的快捷键
- MultiSet和Set的区别
- ArcGIS For JavaScript API 默认参数
- C++继承时的对象内存位置(一)
- TopPaper：AI 初学者经典论文列表
- flink streamGraph生成
- document 对象 html文档内容
- Swift去除两边的特定字符（空格或其它）
- 如何去除小程序button的边框
- EndNote x8基础使用教程(一)
- 超级SIM卡 SEID号读取 手机NFC门禁刷卡模块方案
- oracle 弱口令扫描器,超级弱口令检查工具
- gentoo适合做服务器系统吗,Mandriva、Gentoo发行版
- Java Wed学习总结
- 18个谷歌搜索技巧，让你受用终身
- Aspose for Java 去除水印和数量限制
- java android 计算两个日期之间的天数
- 不容错过的精美的树形表格treegrid在项目里面使用总结
- 博客搬家到Octopress（Mac）