Reader.prototype.watchEvent race condition

[crazy-man]

Hello Matt!
We've discovered another bug that causes unexpected behavior.
The scenario is: mail.log is changed (change event) and right after that log is being rotated(rename event).
It happens at index.js line 332:
At that point we stopped watcher from listening to duplicate events.
But, rename event is not handled as well.

What actually happens is:
slr.createStream() is called after slr.watchDelay, but by that time the file is being moved(logrotated) and new one might now be created.
And in case file exists, looks like slr.sawEndOfFile is not set to false, so safe-log-reader just stops watching mail.log
What I get is:
[2017-04-25 16:14:38.453] opening for read: /var/log/mail.log
[2017-04-25 16:14:38.454] end of /var/log/mail.log
[2017-04-25 16:14:38.454] endStream: dampening extra EOF

and that's it.
After 6 hours log-ship-elastic-postfix is shut down by internal watchdog.

Is it a known issue, or I am missing something?

Thank you,
Constantine

[msimerson]

I expect this is due to a variation in the implementation of whatever is rotating your logs. I haven't the time to dig into it, but if it did the questions I'd be asking are: OS, version, and the log rotation mechanism. There's also variations in the information available in the fs events we receive, which differs by OS and version as well.