Filebeat is unable to read file for 4 hours every day

Elastic Stack Beats
1

Hi all,
I have had filebeat 2.3 running successfully for several months on several Ubuntu 16.04 servers. The other week I installed logrotate and configured cron to run it every hour.
After logrotate was installed filebeat stopped processing new events between 20.00 and 24.00 UTC. Every day.. At 00.00 it starts processing new events again. This happens also if I disable the cron job that runs logrotate. If the log file is rotated sometime between 20 and 24, filebeat recognises that, sends the first event, and then refuses to send any more events.

Enabling debug logs shows that filebeat gets EOF when reading the log file from the saved offset. Restarts of filebeat doesn't help. If I manually set the the offset in the registry file to the next byte, filebeat reads an event, and then stops reading again.

This happens also with latest filebeat 5.x.
I have verified that filebeat use the correct inode.
Using lsof doesn't show anything unexpected.

Filebeat conf:

filebeat:
    prospectors:
    -
        paths:
        - "/var/log/disco/*/*.log"
        document_type: beats
        input_type: log
        fields_under_root: true
        scan_frequency: 2s
        multiline:
            pattern: ^xyz
            negate: true
            match: after
output:
  logstash:
      hosts: ["10.0.3.55:5044", ]
      loadbalance: true
logging:
    level: info
    to_files: true
    to_syslog: false
    files:
        path: /var/log/filebeat
        name: mybeat.log
        keepfiles: 7

Log example:

2017-03-07T19:59:34Z INFO Events sent: 393
2017-03-07T19:59:34Z INFO Registry file updated. 1 states written.
2017-03-07T19:59:42Z INFO Events sent: 446
2017-03-07T19:59:42Z INFO Registry file updated. 1 states written.
2017-03-07T19:59:47Z INFO Events sent: 368
2017-03-07T19:59:47Z INFO Registry file updated. 1 states written.
2017-03-07T19:59:55Z INFO Events sent: 650
2017-03-07T19:59:55Z INFO Registry file updated. 1 states written.
2017-03-07T20:00:03Z INFO Events sent: 471
2017-03-07T20:00:03Z INFO Registry file updated. 1 states written.
2017-03-07T20:00:09Z INFO Events sent: 12
2017-03-07T20:00:09Z INFO Registry file updated. 1 states written.

And then complete silence. Until 00.00 when it starts again.
Some debug logs:

2017-03-07T20:38:06Z DBG  Start next scan
2017-03-07T20:38:06Z DBG  scan path /var/log/disco/*/*.log
2017-03-07T20:38:06Z DBG  Check file for harvesting: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:06Z DBG  Same file as before found. Fetch the state.
2017-03-07T20:38:06Z DBG  Update existing file for harvesting: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:06Z DBG  Not harvesting, file didn't change: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:07Z DBG  Flushing spooler because of timeout. Events flushed: 0
2017-03-07T20:38:07Z DBG  End of file reached: /var/log/disco/haproxy/haproxy.log; Backoff now.
2017-03-07T20:38:08Z DBG  End of file reached: /var/log/disco/haproxy/haproxy.log; Backoff now.
2017-03-07T20:38:08Z DBG  Start next scan
2017-03-07T20:38:08Z DBG  scan path /var/log/disco/*/*.log
2017-03-07T20:38:08Z DBG  Check file for harvesting: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:08Z DBG  Same file as before found. Fetch the state.
2017-03-07T20:38:08Z DBG  Update existing file for harvesting: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:08Z DBG  Not harvesting, file didn't change: /var/log/disco/haproxy/haproxy.log
2017-03-07T20:38:09Z DBG  End of file reached: /var/log/disco/haproxy/haproxy.log; Backoff now.
2017-03-07T20:38:10Z DBG  End of file reached: /var/log/disco/haproxy/haproxy.log; Backoff now.

Any ideas?

BR / Jonas

2

Turns out that it only is files that are written by rsyslog that are affected. Log files that are written by Java, or by just manually appending lines to a file using echo, are read properly and events are forwarded by filebeat.
I wonder if rsyslog is adding any control chars or something.

3

SOLVED.
Obviously it was the multiline pattern that I used. Which worked until I changed the haproxy logging conf at the same time as I did the other changes...

Hope my mistake helps someone else :slight_smile:

1 Like
4

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