[IO-528] fix Tailer.run race condition runaway logging

[davidmoten]

Tailer.run has a race condition that can have serious effects.

The run() method has two while loops. The first waits till the file exists and the second loop reads lines from the file doing some file rotation checking on the way. If the file is deleted while the second loop is in progress then the loop goes crazy logging warnings that look like this:

Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileRotated
INFO: file rotated
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileNotFound
WARNING: file not found
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileRotated
INFO: file rotated
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileNotFound
WARNING: file not found
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileRotated
INFO: file rotated
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileNotFound
WARNING: file not found
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileRotated
INFO: file rotated
Dec 06, 2016 1:02:18 AM com.github.davidmoten.logan.LogFile$1 fileNotFound
WARNING: file not found

In our case this had serious effects. The file being tailed was deleted by another process and all available disk space was rapidly used up by the logging. This crashed a system.

The fix is to put a sleep after the call to fileNotFound().

I haven't made a unit test because reliably triggering this problem would involve a major refactor of the run method to make it testable.

[davidmoten]

No idea why the travis build didn't start. Perhaps an administrator can restart the build.

[coveralls]

Coverage increased (+0.02%) to 90.098% when pulling b6c1334 on davidmoten:fix-tailer-race-condition into 5463164 on apache:master.

[davidmoten]

Looking at our logging history this runaway logging has occurred about 20 times in 4 months (but was restricted to <1GB of extra logs each time as the file in question presumably reappeared). The critical day produced 145GB and system crashed. I didn't mention earlier that this occurred on Unix. I imagine that this might not happen on Windows because it would have a lock on the file and prevent the other process deleting it.

[davidmoten]

No response yet, I'm a bit surprised as the effect of this bug is pretty nasty.

[PascalSchumacher]

Thanks! 👍 And sorry for the delay.