Filebeat locks file when logstash is not runnig

eluppol · November 21, 2016, 1:22pm

I'm using filebeat to ship logs created by log4cxx to ELK stack.
When filebeat is running but logstash is not available, log4cxx cannot rotate log file, so it becomes large (log generation speed is about 4 MB per minute, we use log rotation by 1 MB).
I tried to set close_timeout option to 1m, but filebeat still keeps the file open.

Please see the log file generated by filebeat:

gist.github.com

https://gist.github.com/anonymous/a95739b314cda65b6013f51954467085

filebeat.log

2016-11-21T04:35:22-08:00 INFO Home path: [C:\filebeat] Config path: [C:\filebeat] Data path: [C:\\ProgramData\\filebeat] Logs path: [C:\filebeat\logs]
2016-11-21T04:35:22-08:00 INFO Metrics logging every 30s
2016-11-21T04:35:22-08:00 INFO Setup Beat: filebeat; Version: 5.0.0
2016-11-21T04:35:22-08:00 INFO Max Retries set to: 2
2016-11-21T04:35:22-08:00 INFO Activated logstash as output plugin.
2016-11-21T04:35:22-08:00 INFO Flush Interval set to: 1s
2016-11-21T04:35:22-08:00 INFO Max Bulk Size set to: 2048
2016-11-21T04:35:22-08:00 INFO filebeat start running.
2016-11-21T04:35:22-08:00 INFO Registry file set to: C:\ProgramData\filebeat\registry
2016-11-21T04:35:22-08:00 INFO Loading registrar data from C:\ProgramData\filebeat\registry

This file has been truncated. show original

So how to make filebeat not block the file rotation?

ruflin · November 21, 2016, 2:05pm

I assume what you mean by block file rotation is keeping the file open. Because filebeat should not block any file rotation but will keep the file open until data is sent.

As documented here https://www.elastic.co/guide/en/beats/filebeat/5.0/configuration-filebeat-options.html#close-timeout close_timeout will not work if the output is completely blocked.

What is your expect behaviour for filebeat related to the data? Should it just drop the data it did not send so far (means data loss)?

eluppol · November 21, 2016, 6:29pm

Yes, I expect that filebeat will drop the data which it cannot send.
How to achieve this behavior?

ruflin · November 22, 2016, 7:32am

Currently there is no way to do this if your output is completely blocked. One "workaround" here is to use harvester_limit so not too much space is taken up. The disadvantage of this is that the files that are already open are kept and sent when the output gets available again, means some newer files will be dropped after rotation. The files that will be around will still start harvesting if the output comes available again. So I think in your case this is a feasible solution.

eluppol · November 22, 2016, 1:03pm

I tried harvester_limit, but it didn't fix the problem. As I understood from filebeat manual, harvester_limit just sets the maximum number of harvesters, but even the only harvester keeps file open, so it cannot be rotated.
Also I noticed, that when filebeat is running and output is blocked, it locks only the last one file (log4cxx.log.10), so I cannot delete it by hand.
Is there any other way to close files when output is blocked? Or maybe some way to use other output (for example to file) when logstash output is blocked?

ruflin · November 22, 2016, 1:26pm

The behaviour that you describe is what is expected with the harvester_limit. I'm not sure why you mention that the file cannot be rotated? It should be possible to rename / rotate file, only deletion is not happening. So what you normally end up with is that you have several "deleted but open" files with the same name. What are you using for log rotation?

eluppol · November 22, 2016, 1:53pm

I'm using log4cxx RollingFileAppender configured to rotate files every 1MB.
The problem is only with the last file, which cannot be deleted and as I understand it leads to situation when logs are accumulated in the original log file (log4cxx.log), so it becomes very large. When I stop filebeat, rotation process is resumed immediately, so log4cxx.log becomes log4cxx.log.1, log4cxx.log.1 becomes log4cxx.log.2 and so on... and log4cxx.log.10 is removed.

ruflin · November 22, 2016, 2:41pm

Seems to be the day of RollingFileAppender: Log entries gets truncated on file rotation Or is this other thread somehow related / same company?

The part I still didn't understand about RollingFileAppender is when the initial file gets truncated / removed?

eluppol · November 22, 2016, 3:38pm

Yeah, but I don't think this thread is somehow related

We use RollingFileAppender with MaxBackupIndex set to 10, so it creates only 10 files during log rotation.

As I understand, RollingFileAppender just removes the last file, renames the initial file and all the subsequent files, and then new initial file is created.
As an example I tried to configure filebeat to read only from initial file. The rotation process stalled when initial file became the last one and I think RollingFileAppender couldn't remove it because it was opened by filebeat.

ruflin · November 23, 2016, 10:59am

Ok, that sounds like "normal" log rotation. What is your operating system / file system? I see some Windows path in your logs? This could be a Windows related issue

eluppol · November 23, 2016, 11:22am

We're using Windows Server 2008 R2 Enterprise and NTFS file system.

ruflin · November 25, 2016, 10:24am

Do you get any errors from log4j when it tries to rotate / remove the file? I currently assume on Windows deleted but still open files can't have the same name (possible on Linux). As the file is not deleted, log rotation is actually blocked. So instead of having open file handlers on deleted files like on windows, the initial file written to is constantly growing.

Here is a github issue where we are discussing about a config option like drop_events or similar which would solve this issue: https://github.com/elastic/beats/issues/2395 But it would mean losing events.

system · December 23, 2016, 10:24am

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.