Filebeat blocked after bulk file insertion

[Marco_Lagalla]

Hi all,

I am running an ELK platform where Filebeat is installed as agent in a container, monitoring a file written by Nginx.

This nginx gets close to 30mln of requests at day. The ingestion of access logs is performing really well and logs are sent in near real time to logstash.

By the way, sometimes (once a day at least), our application stops serving requests for a few minutes (5-10 minutes) and close to 200-250k error logs are produced in bulk.

Here come the issue, when error logs are written into the error.log file, which is also monitored by nginx, filebeat hangs and stops sending both access and error logs until we restart it.

Is there some advice on how to tune filebeat configuration to support the parsing of files with such a usage pattern? It can be good also to have error logs ingested with a small delay.

Many thanks,

Marco

[ChrsMark (Chris Mark)]

Hi @Marco_Lagalla ,

do you have any Filebeat's logs to share? There might a good indicator inside there about the reason of the issue you observe.

C.

[Marco_Lagalla]

Hi,

yes, I have just retrieved the logs just now, when the issue with filebeat is happened:

{"log.level":"info","@timestamp":"2022-10-05T09:16:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4090},"total":{"ticks":58760,"time":{"ms":30},"value":0},"user":{"ticks":54670,"time":{"ms":30}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5370081},"version":"8.3.3"},"memstats":{"gc_next":51357272,"memory_alloc":25408152,"memory_total":15331024800,"rss":126259200},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2048},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":1.31,"15":1.75,"5":1.35,"norm":{"1":0.655,"15":0.875,"5":0.675}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:17:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4090},"total":{"ticks":58760,"value":0},"user":{"ticks":54670}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5400081},"version":"8.3.3"},"memstats":{"gc_next":51357272,"memory_alloc":25701344,"memory_total":15331317992,"rss":126259200},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2048},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.94,"15":1.71,"5":1.25,"norm":{"1":0.47,"15":0.855,"5":0.625}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:17:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4090},"total":{"ticks":58760,"value":0},"user":{"ticks":54670}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5430081},"version":"8.3.3"},"memstats":{"gc_next":51357272,"memory_alloc":25879904,"memory_total":15331496552,"rss":126259200},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2048},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.96,"15":1.68,"5":1.23,"norm":{"1":0.48,"15":0.84,"5":0.615}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:18:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100,"time":{"ms":10}},"total":{"ticks":58780,"time":{"ms":20},"value":0},"user":{"ticks":54680,"time":{"ms":10}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5460082},"version":"8.3.3"},"memstats":{"gc_next":51357272,"memory_alloc":26173488,"memory_total":15331790136,"rss":126259200},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2048},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":1.11,"15":1.67,"5":1.24,"norm":{"1":0.555,"15":0.835,"5":0.62}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:18:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100},"total":{"ticks":58870,"time":{"ms":90},"value":0},"user":{"ticks":54770,"time":{"ms":90}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5490082},"version":"8.3.3"},"memstats":{"gc_next":51356216,"memory_alloc":46677784,"memory_total":15353321232,"rss":128131072},"runtime":{"goroutines":43}},"filebeat":{"events":{"added":2048,"done":2048},"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"acked":2048,"active":2740,"batches":3,"total":2740},"read":{"bytes":54},"write":{"bytes":228053}},"pipeline":{"clients":2,"events":{"active":4118,"published":2048,"total":2048},"queue":{"acked":2048}}},"registrar":{"states":{"current":2,"update":2048},"writes":{"success":1,"total":1}},"system":{"load":{"1":1.42,"15":1.69,"5":1.32,"norm":{"1":0.71,"15":0.845,"5":0.66}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:19:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100},"total":{"ticks":58870,"value":0},"user":{"ticks":54770}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5520081},"version":"8.3.3"},"memstats":{"gc_next":51356216,"memory_alloc":46853888,"memory_total":15353497336,"rss":128131072},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":1.4,"15":1.68,"5":1.33,"norm":{"1":0.7,"15":0.84,"5":0.665}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:19:50.323Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100},"total":{"ticks":58880,"time":{"ms":10},"value":0},"user":{"ticks":54780,"time":{"ms":10}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5550081},"version":"8.3.3"},"memstats":{"gc_next":51356216,"memory_alloc":47108520,"memory_total":15353751968,"rss":128131072},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":1.08,"15":1.65,"5":1.27,"norm":{"1":0.54,"15":0.825,"5":0.635}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:20:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100},"total":{"ticks":58880,"value":0},"user":{"ticks":54780}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5580080},"version":"8.3.3"},"memstats":{"gc_next":51356216,"memory_alloc":47449952,"memory_total":15354093400,"rss":128401408},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.99,"15":1.62,"5":1.23,"norm":{"1":0.495,"15":0.81,"5":0.615}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:20:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4100},"total":{"ticks":58910,"time":{"ms":30},"value":0},"user":{"ticks":54810,"time":{"ms":30}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5610081},"version":"8.3.3"},"memstats":{"gc_next":58126280,"memory_alloc":28699936,"memory_total":15354262616,"rss":128401408},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.72,"15":1.58,"5":1.14,"norm":{"1":0.36,"15":0.79,"5":0.57}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:21:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4110,"time":{"ms":10}},"total":{"ticks":58920,"time":{"ms":10},"value":0},"user":{"ticks":54810}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5640082},"version":"8.3.3"},"memstats":{"gc_next":58126280,"memory_alloc":28959232,"memory_total":15354521912,"rss":128942080},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.69,"15":1.55,"5":1.09,"norm":{"1":0.345,"15":0.775,"5":0.545}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:21:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4110},"total":{"ticks":58920,"value":0},"user":{"ticks":54810}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5670081},"version":"8.3.3"},"memstats":{"gc_next":58126280,"memory_alloc":29303640,"memory_total":15354866320,"rss":128942080},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.82,"15":1.53,"5":1.08,"norm":{"1":0.41,"15":0.765,"5":0.54}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:22:20.323Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4110},"total":{"ticks":58920,"value":0},"user":{"ticks":54810}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5700081},"version":"8.3.3"},"memstats":{"gc_next":58126280,"memory_alloc":29505992,"memory_total":15355068672,"rss":128942080},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.56,"15":1.49,"5":1,"norm":{"1":0.28,"15":0.745,"5":0.5}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:22:50.326Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4120,"time":{"ms":10}},"total":{"ticks":58950,"time":{"ms":30},"value":0},"user":{"ticks":54830,"time":{"ms":20}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5730080},"version":"8.3.3"},"memstats":{"gc_next":45117048,"memory_alloc":22284200,"memory_total":15355376304,"rss":115302400},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.6,"15":1.46,"5":0.96,"norm":{"1":0.3,"15":0.73,"5":0.48}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:23:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4120},"total":{"ticks":58950,"value":0},"user":{"ticks":54830}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5760081},"version":"8.3.3"},"memstats":{"gc_next":45117048,"memory_alloc":22580072,"memory_total":15355672176,"rss":115302400},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.9,"15":1.45,"5":1,"norm":{"1":0.45,"15":0.725,"5":0.5}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:23:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4120},"total":{"ticks":58960,"time":{"ms":10},"value":0},"user":{"ticks":54840,"time":{"ms":10}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5790081},"version":"8.3.3"},"memstats":{"gc_next":45117048,"memory_alloc":22840016,"memory_total":15355932120,"rss":115302400},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.61,"15":1.41,"5":0.92,"norm":{"1":0.305,"15":0.705,"5":0.46}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:24:20.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4130,"time":{"ms":10}},"total":{"ticks":58970,"time":{"ms":10},"value":0},"user":{"ticks":54840}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5820081},"version":"8.3.3"},"memstats":{"gc_next":45117048,"memory_alloc":22964984,"memory_total":15356057088,"rss":115302400},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.66,"15":1.39,"5":0.91,"norm":{"1":0.33,"15":0.695,"5":0.455}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:24:50.324Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4130},"total":{"ticks":58990,"time":{"ms":20},"value":0},"user":{"ticks":54860,"time":{"ms":20}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5850081},"version":"8.3.3"},"memstats":{"gc_next":45112152,"memory_alloc":22195856,"memory_total":15356314680,"rss":112488448},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.87,"15":1.39,"5":0.95,"norm":{"1":0.435,"15":0.695,"5":0.475}}}},"ecs.version":"1.6.0"}}
{"log.level":"info","@timestamp":"2022-10-05T09:25:20.326Z","log.logger":"monitoring","log.origin":{"file.name":"log/log.go","file.line":185},"message":"Non-zero metrics in the last 30s","service.name":"filebeat","monitoring":{"metrics":{"beat":{"cpu":{"system":{"ticks":4140,"time":{"ms":10}},"total":{"ticks":59000,"time":{"ms":10},"value":0},"user":{"ticks":54860}},"handles":{"limit":{"hard":4096,"soft":1024},"open":13},"info":{"ephemeral_id":"9f808cef-6497-4529-8b88-75c4c5f1ce68","uptime":{"ms":5880083},"version":"8.3.3"},"memstats":{"gc_next":45112152,"memory_alloc":22576736,"memory_total":15356695560,"rss":112488448},"runtime":{"goroutines":43}},"filebeat":{"harvester":{"open_files":2,"running":2}},"libbeat":{"config":{"module":{"running":0}},"output":{"events":{"active":2740},"read":{"bytes":36}},"pipeline":{"clients":2,"events":{"active":4118}}},"registrar":{"states":{"current":2}},"system":{"load":{"1":0.95,"15":1.38,"5":0.97,"norm":{"1":0.475,"15":0.69,"5":0.485}}}},"ecs.version":"1.6.0"}}

[ChrsMark (Chris Mark)]

I would try to tune Configure the Elasticsearch output | Filebeat Reference [8.4] | Elastic . Also try to run Filbeat with debug logs enabled so as to see what actually happens when Filebeat seems hanged.