Filebeat rotation issue (windows)

Elastic Stack Beats
1

Hey,

i'm experiencing an rotation issue on my windows machines.
machine: Windows 2012 R2
version: 1.3.1
configurations:
global config: https://nopaste.me/view/9ef7645a
prospector config: https://nopaste.me/view/cf174611

I detected that files are read twice, so i decided to add debugging statements to the following line: https://github.com/elastic/beats/blob/v1.3.1/filebeat/crawler/registrar.go#L205

        for oldFilePath, oldState := range r.getStateCopy() {

+               logp.Info("CHECK STATE: new:%s old:%s", newFilePath, oldFilePath)
+               logp.Info("CHECK STATE: new:%s %s %s", newState.IdxHi, newState.IdxLo, newState.Vol)
+               logp.Info("CHECK STATE: old:%s %s %s", oldState.FileStateOS.IdxHi, oldState.FileStateOS.IdxLo, oldState.FileStateOS.Vol)

The result is the following: https://nopaste.me/view/3a013b38 . The application3.log is renamed to C:/server/wildfly/standalone/log/application3.log.2016-09-27 and a new application3.log is created.
On the LOG you can see that the call "Prospector.scan -> Registrar.fetchState -> Registrar.getPreviousFile" will be executed twice (for the new and renamed file).

First the new file is checked against r.getStateCopy() and afterwards the renamed file too.
Because Prospector.scan and therefore (p.checkNewFile / p.checkExistingFile) will start an harvester and do an registrar state update ("p.registrar.Persist <- h.GetState()"),
the state of the old file is overridden and for the second run (renamed run), there is no state available to check against. Therefore the renamed file will be read twice.

Workaround seems to be setting the glob of the rotated files first and then the glob of the original file. In addition this problem occours only sometimes if the state-update is faster than the Prospector.scan. Any ideas, since this behavior is undocumented and annoying?

Regards
Hajo

2

The best workaround for the above is using the 5.0 release as in 5.0 the state mechanism was rewritten to prevent all these race conditions. Because of the way 1.x works, there is currently no way to completely prevent this without causing other race conditions. The problem mainly happens if there is a low scan_frequency value and lots of files. In your case I would recommend to increase the scan_frequency. But this only "reduces" the likely hood, it does not prevent it.

Thanks for digging so deep into the code and identifying the problem. Can you elaborate what you mean by Workaround seems to be setting the glob of the rotated files first and then the glob of the original file?

3

Hey, please ignore this assumption because the file is read twice regardless of the file pattern order. The order of file pattern will just fix another bug related to recognition of file change and info message "Old file with new name found:", which is missing if the pattern order is ["file.log", "file.log.2016-01-01"] but is present on ["file.log.2016-01-01", "file.log"]

EDIT: its working with 5.0

Regards
Hajo

4

Did you have a chance to test if this behaviour disappears in the 5.0 version?

5

This topic was automatically closed after 21 days. New replies are no longer allowed.