LS > 1.5.1 double ingestion of log when rotated based on glob path

[thomasquatorze]

Starting with LS 1.5.2 logs referenced with a glob path start being ingested a second time as the log is being rotate at 00:00 UTC. sincedb file content initially shows the log (inode 16648175) changing name (access_logstash.log -> access_logstash.log.2015-07-30) but then no longer being tracked. Kibana shows doubling of log volume starting 00:00 UTC the previous day. stopping ls, removing the sincedb file and starting ls resets the problem until the next rotation.

Testing was run on 2 identical systems. The one using no globs in path, did not experience the problem.

os: Ubuntu 12.04.5 LTS (precise)
pkg: logstash_1.5.3-1_all.deb (025e540e9276946871396a739042acbdd93d4e6f)
java: oracle 1.7.0_51

path => "/var/opt/tomcat/tomcat-*/logs/access_logstash.log*"
-----------------------------------------------------------------------------------------

2015-07-30-23:59:55
16648175 0 2054 59565616529 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log - Bytes/Offset: 59569433018/59565616529
16693500 0 2054 63156842952 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log.2015-07-29 - Bytes/Offset: 63156842952/63156842952

2015-07-31-00:00:00
16693500 0 2054 63156842952 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log.2015-07-29 - Bytes/Offset: 63156842952/63156842952
16648175 0 2054 59565616529 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log.2015-07-30 - Bytes/Offset: 59572896325/59565616529

2015-07-31-00:00:10
16649716 0 2054 5517424     - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log - Bytes/Offset: 8887555/5517424
16693500 0 2054 63156842952 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log.2015-07-29 - Bytes/Offset: 63156842952/63156842952

path => "/var/opt/tomcat/tomcat-8080/logs/access_logstash.log"
-----------------------------------------------------------------------------------------

2015-07-30-23:59:58
16386949 0 2054 59566214989 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log - Bytes/Offset: 59576407646/59566214989

2015-07-31-00:00:03
16386949 0 2054 59577724637 - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log.2015-07-30 - Bytes/Offset: 59577724637/59577724637

2015-07-31-00:00:18
16385849 0 2054 12814313    - /var/opt/tomcat/tomcat-8080/logs/access_logstash.log - Bytes/Offset: 15460725/12814313

[thomasquatorze]

It appears that even a single glob in the filename (no glob in path), still triggers this condition
path => "/var/opt/tomcat/tomcat-8080/logs/access_logstash.log*"

[thomasquatorze]

To easily reproduce the problem with basic file input/output (used logstash 1.5.2):

input {
  file {
    path => "/var/tmp/access_log.*"
  }
}

output {
  file {
    path => "/var/tmp/access_log_output.log"
  }
}

And generating logs slowly so as to give logstash time to discover new logs (default discover_interval 15 seconds)

#!/usr/bin/env bash

LOGFILE="/var/tmp/access_log.log"

for ((x=1;x<=30;x++)) ; do
  echo "logging some data ${x}" >> ${LOGFILE}
  sleep 1
  if [ ${x} == 15 ] ; then
   mv ${LOGFILE} ${LOGFILE}.`date '+%Y.%M.%d.%H-%M-%S'`
  fi
done

Data written to 1st log (that is rotated) is output-ed twice to output log.

count  log
-----  -----------------------------------
15     /var/tmp/access_log.log
15     /var/tmp/access_log.log.2015.22.03.16-22-13
45     /var/tmp/access_log_output.log

[jsvd]

This bug was introduced with jordansissel/ruby-filewatch#51
The reason behind the PR was that deleting a file then creating a new one could render the new file invisible to filewatch if it ended up with the same inode number.
I need to run some tests but we need to reverse that patch in some way, as this is a critical bug.

[jsvd]

After merging the filewatch PR we still need to release a new version of the filewatch library and then update the .lock file for the 1.5.4 release

[jsvd]

Filewatch 0.6.5 has been released with a fix for this.
I have created a pr to force its use in logstash-input-file logstash-plugins/logstash-input-file#64

[jsvd]

logstash-input-file 1.0.1 has been released, needs to be included in the next release of logstash (1.5.4)

[thomasquatorze]

manually installing logstash-input-file 1.0.1 plugin in logstash 1.5.2 appears to resolve the issue when running the test detailed in #3674 (comment). I'll run a production test to validate fix with tomcat logs rotated by tomcat at 00:00 UTC

[jsvd]

Thank you for testing this @thomasquatorze

[thomasquatorze]

Updated the logstash-input-file plugin to 1.0.1 on a production host running logstash 1.5.3 and it properly handled log rotation by tomcat/log4j at 00:00 UTC. This issue appears to be resolved. Thanks

[jsvd]

Thank you again! this will be included in 1.5.4