Filebeat wrongly detects a log rename in rotation, causing "Not resuming rotated file"

Elastic Stack Beats
1

Hello, I have a problem with one of my log files in Filebeat 1.3.1:

Not resuming rotated file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log

This happens all the time, until this pops up (with a typo, as I assume "no" should be "now"):

Harvester started for file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log
2018-02-07T11:30:06+01:00 INFO File was truncated. Begin reading file from offset 0: /cerebrum/var/log/cerebrum/exchange_daemon.py/log
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.9 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.9 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.1
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.1
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.1 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.2
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.1 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.2
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.2 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.3
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.2 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.3
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.3 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.4
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.3 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.4
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.4 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.5
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.4 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.5
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.5 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.6
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.5 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.6
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.6 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.7
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.6 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.7
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.7 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.8
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.7 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.8
2018-02-07T12:50:06+01:00 INFO Old file with new name found: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.8 is no /cerebrum/var/log/cerebrum/exchange_daemon.py/log.9
2018-02-07T12:50:06+01:00 INFO Detected rename of a previously harvested file: /cerebrum/var/log/cerebrum/exchange_daemon.py/log.8 -> /cerebrum/var/log/cerebrum/exchange_daemon.py/log.9

And then it resumes telling me it's not resuming the rotated file. Now, if we look at the log messages above, they seem sensible enough: Our rotation has incremented the number at the end of every log file.

However, as we see at the top, filebeat seems to think that the new log file with no number at the end is a renamed log.9 file. That's not the case; the ninth log file is deleted and the file with no number suffix is new (which filebeat does seem to notice, since it says it's truncated). The rotation doesn't wrap (so it's more like a shift, hehe).

I'm not sure why filebeat would erroneously detect a rename here. At any rate, it leads to a lot of dropped log lines. This is my config:

- paths:
    - /cerebrum/var/log/cerebrum/job_runner.py/log*
  input_type: log
  multiline:
    pattern: '^[0-9]{4}-[0-9]{2}-[0-9]{2}'
    negate: true
    match: after
  fields:
    logowner: usit-cerebrum
    application: job_runner
    instance: uio
  fields_under_root: true
  document_type: log
2

Is upgrading to the latest version of Filebeat is viable for you?
Reading from files and handling file rotation has been refactored since. Your problem should be solved in later versions.

3

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