Hello,
We're in some strange behavior with our Filebeat.
Here the facts:
- filebeat 1.2.3
- windows server (2012 r2 I think)
- we use log4j2 for logging
- current/active logging file is named like this: acces.log, audit.log, application.log
- each file is rotated based on size (25mb) or day change
- when rotated, file moved to subfolder named YYYY-MM, and filename prefixed with YYYY-MM-DD and appended %i where %i is a daily sequence number
- each file is rotated when we cross the day at midnight, so each file contains only event from its tagged day in name
Last week we were hit by file modification date not changing for hours or at worst not changing from 00:00 (midnight).
Some search brought us to this known problem:
So we increased our close_older setting from 1h to 30h to easily cover our worst case of single daily moddate (00:00).
Also, we always ensured that our globs covers current files as rotated ones.
One of our prospector config:
filebeat:
prospectors:
-
paths:
# CURRENT FILES: d:\logs\[domain]\[managed server]\[application name]\
- d:\logs\*\*\*\acces.log
# ROTATED FILES: d:\logs\[domain]\[managed server]\[application name]\YYYY-MM\
- d:\logs\*\*\*\*\*-acces-*.log
document_type: acces
encoding: iso8859-1
input_type: log
ignore_older: 168h
close_older: 30h
scan_frequency: 10s
force_close_files: false
We though it will fix everything, but looking at logs surrounding midnight I can see a lot of event sent when rotation occurs. Our spool size (4096) is flushed many times, a sign that something odd is occuring.
Here's the filebeat log at midnight: filebeat-midnight-rotation-log · GitHub
When looking at Elasticsearch, I can see duplicates for the same events.
Easy to confirm the duplicates as:
- we're on very low activity at midnight, and spool size never hit the day on our summer load
- events are timestamped at milisecond level
So, is it a bug or misconfiguration on our side?
Thanks
Bruno
