Logstash holding deleted output file

Elastic Stack Logstash
1

I am currently using logstash with version 7.17 in the docker. Here is my output code:

output{
file{
 path=>"/tmp/data/output.log"
}
}

Meanwhile, I also have logrotate to keep it rotating:

/tmp/data/output.log {
   size 5G
   rotate 1
   daily
   missingok
   su root adm
}

However, sometimes I found that the logstash will keep opening the rotated file such as /tmp/data/output.log-20220201 when I am checking in the lsof | grep "deleted". The disk could not be freed because of this. Currently, the only way to free the disk is to kill the logstash process and restart it. This never happened before.

2

The call to close_stale_files can only occur if events are received by the output. If there are no more events then the file will never get closed.

You could enable log.level debug and confirm that you do not get the "Starting stale files cleanup cycle" message.

3

Then how can we set some configuration to close the file if that happens?

4

I have not tested this but you could add an additional input

heartbeat { interval => 20 add_field => { "[@metadata][filename]" => "/dev/null" } }

Then in the filter section, add that field if it is missing

 if ! [@metadata][filename] { mutate { add_field => { "[@metadata][filename]" => "/home/user/data/file" } }

and in the output section sprintf the path option in the file output

file { path => "%{[@metadata][filename]}" ... }

You will always have a file descriptor open to /dev/null, but /home/user/data/file will get closed. The test of whether a file is active is done immediately after events are processed, so if the path option is a constant the file will never be inactive.

Note that there is an open issue for this and the code changes needed are trivial.

5

Looks like the logstash can not be executed under "/" folder since it will give this error:

File: The starting part of the path should not be dynamic. {:path=>"/%{[@metadata][filename]}"}

However if we execute this under some other directory like /home/ec2-user. There will be some outputs in /home/ec2-user/dev/null files:

"host":"xxxxxx","message":"ok","@timestamp":"2022-02-04T01:26:19.019Z","@version":"1"}

which will still take some spaces in the disk (around 1k per message).

As it is stated, " If you use an absolute path you cannot start with a dynamic string. E.g: /%{myfield}/ , /test-%{myfield}/ are not valid paths". Thus, when the path is a variable/dynamic, the Logstash won't use the absolute path.

So what about this:
changes in input

heartbeat { interval => 20 add_field => { "[@metadata][filename]" => "heartbeat.log" } }

change output:

file { path => "/tmp/%{[@metadata][filename]}" ... }

And delete this /tmp/heartbeat.log by crontab every minute. I am not sure whether this idea is same as yours.

6

Yeah, if @path contains a sprintf reference it is expanded relative to the working directory. If you try to add a / before the sprintf reference then you get an exception. The following works if you ln -s /dev/null /tmp/null

input { generator { count => 1 lines => [ 'Hello, world!' ] } }
input { heartbeat { interval => 20 add_field => { "[@metadata][filename]" => "null" } } }
filter {
    if ! [@metadata][filename] { mutate { add_field => { "[@metadata][filename]" => "file.txt" } } }
}
output { file { path => "/tmp/%{[@metadata][filename]}" } }
output { stdout { codec => rubydebug { metadata => false } } }

However, this issue tells me that when java_execution is enabled, an empty batch is sent through the pipeline every 15 seconds, so multi_receive_encoded is called to process a batch that contains no events. That's enough to get close_stale_files called.

So you can get the behaviour you want by enabling the Java execution engine, which is the only choice you have when 8.0 arrives.

7

The holding spaces were immediately released after config file changed as it is mentioned and pipeline reloaded. I am not sure whether it is worked by reloading the pipeline or heartbeat events. So I will continue to monitor the disk usage to see if the issue is resolved. Thanks.

8

It seems that this method does not work. I can still find the holding deleted files in the lsof. 31631 is the logstash pid

java      31631                   root  137u      REG                8,1 17111301202    1044321 /tmp/xxxxx.log-20220205 (deleted)

Here is the segment of the log

[2022-02-08T18:57:33,961][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Opening file {:path=>"/tmp/null"}
[2022-02-08T18:57:47,520][INFO ][logstash.outputs.file    ][test_pipeline_3][1e42fcfd759972cf54792bf99174c9d4c28ff6e07169aae7183ee6d6cf5b202f] Closing file /tmp/null
[2022-02-08T18:57:48,011][INFO ][logstash.outputs.file    ][test_pipeline_3][1e42fcfd759972cf54792bf99174c9d4c28ff6e07169aae7183ee6d6cf5b202f] Opening file {:path=>"/tmp/null"}
[2022-02-08T18:57:53,137][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Closing file /tmp/null
[2022-02-08T18:57:53,940][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Opening file {:path=>"/tmp/null"}
[2022-02-08T18:58:03,224][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Closing file /tmp/xxxxx.log
[2022-02-08T18:58:03,628][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Opening file {:path=>"/tmp/xxxxx.log"}
[2022-02-08T18:58:07,628][INFO ][logstash.outputs.file    ][test_pipeline_3][1e42fcfd759972cf54792bf99174c9d4c28ff6e07169aae7183ee6d6cf5b202f] Closing file /tmp/null
[2022-02-08T18:58:08,034][INFO ][logstash.outputs.file    ][test_pipeline_3][1e42fcfd759972cf54792bf99174c9d4c28ff6e07169aae7183ee6d6cf5b202f] Opening file {:path=>"/tmp/null"}
[2022-02-08T18:58:13,237][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Closing file /tmp/null
[2022-02-08T18:58:13,939][INFO ][logstash.outputs.file    ][test_pipeline_2][5e480e8e9e336d09064fa30153eeb2c57764a38a97f2477c28d808b6239bdbf2] Opening file {:path=>"/tmp/null"}
[2022-02-08T18:58:27,660][INFO ][logstash.outputs.file    ][test_pipeline_3][1e42fcfd759972cf54792bf99174c9d4c28ff6e07169aae7183ee6d6cf5b202f] Closing file /tmp/null

It seems that the events kept coming, but for some reason it does not trigger close_stale_files. I don't know why.

It seems that reloading pipeline can release the occupied spaces.

9

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