logstash-forwarder keep deleted files open

[ZhukovAlexey]

It seems that java version has the same bug elastic/logstash-forwarder#200

When a log file is rotated the logstash-forwarder agent keeps the deleted file opened until you kill its service.
This problem obviously causes an unhealthy situation of a consistently decreasing free space on the filesystem and currently my patch solution is scheduled restart for logstash-forwarder by a cron.

$ps -ef | grep forwarder | grep -v grep
wasadm 5981 1 0 Apr 6 ? 177:33 /IBM/WebSphere/AppServer/java/bin/IA64N/java -jar logstash-forwarder-java-0.2.3.jar -config config/ibm-was-system-logs-forwarde
wasadm 24530 1 31 Apr 26 ? 563:04 /IBM/WebSphere/AppServer/java/bin/IA64N/java -jar logstash-forwarder-java-0.2.3.jar -config config/app-albo-logs-forwarder.conf

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 5981
1818

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 24530
1022

[rahulghanate]

Facing the same issue,

# lsof | grep logstash | grep deleted | wc -l
XXX

Using LSF 0.4.0

[didfet]

@rahulghanate I think you're using logstash-forwarder, not logstash-forwarder-java.

[didfet]

@ZhukovAlexey I'm surprised by your problem because I've been careful to track this kind of issues. Some of my instances have been running for months without any problem. It looks like you have a lot of file rotation, maybe this is the reason something is not running properly. Can you send a debug output, maybe it will help find a solution ?

[rahulghanate]

Yup,
I am using logstash-forwarder and not *-java.
I missed to see that in issue details.
But the problem is same.

[rbodoque]

Hi, for me the same error.

I suspect is related to use file match instead of wildcard. I mean my configuration is like

"files": [
    // An array of hashes. Each hash tells what paths to watch and
    // what fields to annotate on events from those paths.
    {
      "paths": [
        "/mnt/logs/server.log"
      ],
      "fields": {"type": "weblogic"}
    }

instead of

"paths": [
        "/mnt/logs/server*.log"
      ]

I've modified the FileWatcherTest.java to reproduce the error. As you can see in the second lsof looks like the file is not closed.

/home/**/git/logstash-forwarder-java/testFileWatcher2.txt (deleted)

I think is could be related to /src/main/java/info/fetter/logstashforwarder/FileWatcher.java

In the line 162 =>

if(otherState != null && state.getSize() >= otherState.getSize() && state.getDirectory().equals(otherState.getDirectory())) {

would not be?

if(otherState != null && state.getSize() ** <=** otherState.getSize() && state.getDirectory().equals(otherState.getDirectory())) {

[didfet]

@rbodoque you're right there's a problem with file match. I think it is located in the removeMarkedFilesFromWatchMap method :

            if(state.isDeleted()) {
                if(! file.exists()) {

Since a new file exists with the same name, the file descriptor is never closed. We'll have to find a way to detect it should be closed even if a new file exists.

[ZhukovAlexey]

Yes, I'm using a wildcard

        {
          "paths":  ["/LOGS/Application/LINK/Link/console.log*"],
          "fields": { "index": "app-albo-logs", "type": "console", "node": "Node02_Link" }
        },
        {
          "paths":  ["/LOGS/Application/LINK/Link2/console.log*"],
          "fields": { "index": "app-albo-logs", "type": "console", "node": "Node02_Link2" }
        },

I've downloaded the new 0.2.4 version and it seems that bug is still here.

28099 is the forwarder's PID

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 28099
0

2016-08-31 16:25:28,949 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link/console.log.2 -> /LOGS/Application/LINK/Link/console.log.3
2016-08-31 16:25:28,949 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link/console.log.3 -> /LOGS/Application/LINK/Link/console.log.4
2016-08-31 16:25:28,949 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link/console.log -> /LOGS/Application/LINK/Link/console.log.1
2016-08-31 16:25:28,949 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link/console.log.1 -> /LOGS/Application/LINK/Link/console.log.2

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 28099
1

2016-08-31 16:26:52,008 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link2/console.log.1 -> /LOGS/Application/LINK/Link2/console.log.2
2016-08-31 16:26:52,008 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link2/console.log -> /LOGS/Application/LINK/Link2/console.log.1
2016-08-31 16:26:52,008 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link2/console.log.3 -> /LOGS/Application/LINK/Link2/console.log.4
2016-08-31 16:26:52,008 INFO FileWatcher - File rename was detected: /LOGS/Application/LINK/Link2/console.log.2 -> /LOGS/Application/LINK/Link2/console.log.3

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 28099
2

And after each rename operation the amount of open files keep growing,

[ZhukovAlexey]

Here is the log with debug option. I hope this will help to determine the problem

$/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 21370
14

And there're 14 "File rename was detected"

logstash-forwarder-java.zip

[didfet]

@ZhukovAlexey can you try with the fix I've just made in branch fix_issue_21 ?

[ZhukovAlexey]

Yes, of course. Can you build a jar file with that fix?

[didfet]

logstash-forwarder-java-0.2.5-FIX-ISSUE-21-bin.zip

[ZhukovAlexey]

@didfet unfortunally it didn't help :(

/usr/local/bin/lsof -a +L1 /LOGS | grep -wc 26157
9

Debug log:
logstash-forwarder-java.zip