Subset of gzip input files being ignored when running in read mode

[xo4n]

When reading gzip files in read mode some are processed while others are put into ignoring state by filewatch. Files are being copied at regular intervals into the input directory and every time a subset is ignored

• Version:
  logstash-6.4.2 with logstash-input-file (4.1.6)

• Operating System:
  Debian GNU/Linux 8.10 (jessie)

• Config File (if you have sensitive info, please remove it):

   input
{
  file 
  {
    path => "/appdata/logs/akme/lds.akme.com/854343/trv*esw3cch*"
    mode => "read"
    file_completed_action => "log_and_delete"
    file_completed_log_path => "/appdata/logstash-6.4.2/data/akme_esw3cch_logs/plugins/inputs/file/logstash_file_completed.log"
    sincedb_path => "/dev/null"
    ignore_older => 360000
    stat_interval => 60
    close_older => 360000
  }
} 

• Sample Data:

akme@logstash:/appdata/logs/akme/lds.akme.com/854343/$ ls -ltrh *cch*
-rw-r--r-- 1 akme akme 15M Nov 19 12:03 trv_jsa_346234.esw3cch_S.201811191000-1100-4.gz
-rw-r--r-- 1 akme akme 19M Nov 19 13:06 trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz
-rw-r--r-- 1 akme akme 40M Nov 19 13:06 trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz
-rw-r--r-- 1 akme akme 40M Nov 19 13:06 trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz
-rw-r--r-- 1 akme akme 16M Nov 19 13:07 trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz
-rw-r--r-- 1 akme akme 16M Nov 19 13:14 trv_imgio_234533.esw3cch_S.201811190900-1000-0.gz
-rw-r--r-- 1 akme akme 40M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-0.gz
-rw-r--r-- 1 akme akme 40M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-1.gz
-rw-r--r-- 1 akme akme 41M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-2.gz
-rw-r--r-- 1 akme akme 41M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-3.gz
-rw-r--r-- 1 akme akme 41M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-4.gz
-rw-r--r-- 1 akme akme 16M Nov 19 13:54 trv_jsa_346234.esw3cch_S.201811191200-1300-5.gz
-rw-r--r-- 1 akme akme 21M Nov 19 13:56 trv_imgio_234533.esw3cch_S.201811191200-1300-0.gz

• Steps to Reproduce:
  Copy a bunch of gzip files into the input directory at regular intervals. The input plugin will process some while ignoring others

• Logs:

[2018-11-19T13:19:28,969][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb
[2018-11-19T13:19:28,965][TRACE][filewatch.readmode.processor] Watched processing
[2018-11-19T13:19:28,965][TRACE][filewatch.readmode.processor] Active processing
[2018-11-19T13:19:28,966][TRACE][filewatch.discoverer     ] discover_files {"count"=>9}
[2018-11-19T13:19:28,966][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-0.gz', @state='watched', @rec
ent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='42192931', last_stat_size='42192931', file_open?='false', @initial=true, @sincedb_key='813382759 0 2053'>"}
[2018-11-19T13:19:28,967][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382759", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-0.gz"}
[2018-11-19T13:19:28,967][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_jsa_346234.esw3cch_S.201811191100-1200-0.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382759", maj=0, min=2053>,
"sincedb_value"=>#<FileWatch::SincedbValue:0x6ffb3c7 @last_changed_at=1542630028.899653, @watched_file=nil, @position=19040815>}
[2018-11-19T13:19:28,967][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb

[2018-11-19T13:19:28,968][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-1.gz', @state='watched', @rec
ent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='41017112', last_stat_size='41017112', file_open?='false', @initial=true, @sincedb_key='813382797 0 2053'>"}
[2018-11-19T13:19:28,968][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382797", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-1.gz"}
[2018-11-19T13:19:28,968][TRACE][filewatch.sincedbcollection] associate: unmatched


[2018-11-19T13:19:28,968][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>false, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191000-1100-4.gz', @state='ignored', @re
cent_states='[:watched, :watched]', @bytes_read='23993046', @bytes_unread='0', current_size='14999447', last_stat_size='14999447', file_open?='false', @initial=false, @sincedb_key='813382786 0 2053'>"}

[2018-11-19T13:19:28,969][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-2.gz', @state='watched', @rec
ent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='41244618', last_stat_size='41244618', file_open?='false', @initial=true, @sincedb_key='813382788 0 2053'>"}
[2018-11-19T13:19:28,969][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382788", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-2.gz"}
[2018-11-19T13:19:28,969][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_jsa_346234.esw3cch_S.201811191100-1200-2.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382788", maj=0, min=2053>,

[2018-11-19T13:19:28,970][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>false, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_imgio_234533.esw3cch_S.201811190900-1000-0.gz', @state='ignored', @
recent_states='[:watched, :watched]', @bytes_read='40516546', @bytes_unread='0', current_size='16112162', last_stat_size='16112162', file_open?='false', @initial=false, @sincedb_key='813382774 0 2053'>"}

[2018-11-19T13:19:28,970][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz', @state='watched', @rec
ent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='41367576', last_stat_size='41367576', file_open?='false', @initial=true, @sincedb_key='813382802 0 2053'>"}
[2018-11-19T13:19:28,970][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382802", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz"}
ent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='41367576', last_stat_size='41367576', file_open?='false', @initial=true, @sincedb_key='813382802 0 2053'>"}
[2018-11-19T13:19:28,970][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382802", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz"}
[2018-11-19T13:19:28,970][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382802", maj=0, min=2053>, "sincedb_value"=>#<FileWatch::SincedbValue:0x328c5163 @last_changed_at=1542627645.026352, @watched_file=nil, @position=42240426>}
[2018-11-19T13:19:28,971][TRACE][filewatch.sincedbcollection] handle_association fully read, ignoring..... {"watched file"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz', @state='ignored', @recent_states='[:watched, :watched]', @bytes_read='42240426', @bytes_unread='0', current_size='41367576', last_stat_size='41367576', file_open?='false', @initial=false, @sincedb_key='813382802 0 2053'>", "sincedb value"=>#<FileWatch::SincedbValue:0x328c5163 @last_changed_at=1542633568.971039, @watched_file="<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-3.gz', @state='ignored', @sincedb_key='813382802 0 2053, size=41367576>", @position=42240426>}
[2018-11-19T13:19:28,971][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb

[2018-11-19T13:19:28,971][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz', @state='watched', @recent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='41853624', last_stat_size='41853624', file_open?='false', @initial=true, @sincedb_key='813382806 0 2053'>"}
[2018-11-19T13:19:28,971][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382806", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz"}
[2018-11-19T13:19:28,972][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382806", maj=0, min=2053>, "sincedb_value"=>#<FileWatch::SincedbValue:0x1b3e8950 @last_changed_at=1542627720.808356, @watched_file=nil, @position=43107870>}
[2018-11-19T13:19:28,972][TRACE][filewatch.sincedbcollection] handle_association fully read, ignoring..... {"watched file"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz', @state='ignored', @recent_states='[:watched, :watched]', @bytes_read='43107870', @bytes_unread='0', current_size='41853624', last_stat_size='41853624', file_open?='false', @initial=false, @sincedb_key='813382806 0 2053'>", "sincedb value"=>#<FileWatch::SincedbValue:0x1b3e8950 @last_changed_at=1542633568.972369, @watched_file="<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-4.gz', @state='ignored', @sincedb_key='813382806 0 2053, size=41853624>", @position=43107870>}
[2018-11-19T13:19:28,972][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb

[2018-11-19T13:19:28,973][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz', @state='watched', @recent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='19867997', last_stat_size='19867997', file_open?='false', @initial=true, @sincedb_key='813382778 0 2053'>"}
[2018-11-19T13:19:28,973][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382778", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz"}
[2018-11-19T13:19:28,973][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382778", maj=0, min=2053>, "sincedb_value"=>#<FileWatch::SincedbValue:0x7a6632dc @last_changed_at=1542626577.87471, @watched_file=nil, @position=42281344>}
[2018-11-19T13:19:28,973][TRACE][filewatch.sincedbcollection] handle_association fully read, ignoring..... {"watched file"=>"<FileWatch::WatchedFile: @filename='trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz', @state='ignored', @recent_states='[:watched, :watched]', @bytes_read='42281344', @bytes_unread='0', current_size='19867997', last_stat_size='19867997', file_open?='false', @initial=false, @sincedb_key='813382778 0 2053'>", "sincedb value"=>#<FileWatch::SincedbValue:0x7a6632dc @last_changed_at=1542633568.973881, @watched_file="<FileWatch::WatchedFile: @filename='trv_imgio_234533.esw3cch_S.201811191100-1200-0.gz', @state='ignored', @sincedb_key='813382778 0 2053, size=19867997>", @position=42281344>}
[2018-11-19T13:19:28,974][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb

[2018-11-19T13:19:28,974][TRACE][filewatch.discoverer     ] discover_files handling: {"new discovery"=>true, "watched_file details"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz', @state='watched', @recent_states='[:watched]', @bytes_read='0', @bytes_unread='0', current_size='16561654', last_stat_size='16561654', file_open?='false', @initial=true, @sincedb_key='813382807 0 2053'>"}
[2018-11-19T13:19:28,974][TRACE][filewatch.sincedbcollection] associate: finding {"inode"=>"813382807", "path"=>"/appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz"}
[2018-11-19T13:19:28,975][TRACE][filewatch.sincedbcollection] associate: found sincedb record {"filename"=>"trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz", "sincedb key"=>#<struct FileWatch::InodeStruct inode="813382807", maj=0, min=2053>, "sincedb_value"=>#<FileWatch::SincedbValue:0x17e95516 @last_changed_at=1542625527.868714, @watched_file=nil, @position=40239579>}
[2018-11-19T13:19:28,975][TRACE][filewatch.sincedbcollection] handle_association fully read, ignoring..... {"watched file"=>"<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz', @state='ignored', @recent_states='[:watched, :watched]', @bytes_read='40239579', @bytes_unread='0', current_size='16561654', last_stat_size='16561654', file_open?='false', @initial=false, @sincedb_key='813382807 0 2053'>", "sincedb value"=>#<FileWatch::SincedbValue:0x17e95516 @last_changed_at=1542633568.9754019, @watched_file="<FileWatch::WatchedFile: @filename='trv_jsa_346234.esw3cch_S.201811191100-1200-5.gz', @state='ignored', @sincedb_key='813382807 0 2053, size=16561654>", @position=40239579>}
[2018-11-19T13:19:28,976][TRACE][filewatch.sincedbcollection] associate: inode matched but no path in sincedb
[2018-11-19T13:20:28,976][TRACE][filewatch.readmode.processor] Watched processing
[2018-11-19T13:20:28,977][TRACE][filewatch.readmode.processor] Active processing
[2018-11-19T13:20:28,977][TRACE][filewatch.readmode.handlers.readzipfile] handling: /appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-0.gz
[2018-11-19T13:21:47,414][DEBUG][filewatch.sincedbcollection] writing sincedb (delta since last write = 3679)
[2018-11-19T13:21:47,415][TRACE][filewatch.sincedbcollection] sincedb_write: to: /dev/null
[2018-11-19T13:21:47,427][TRACE][filewatch.readmode.handlers.readzipfile] handling: /appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-1.gz
[2018-11-19T13:21:47,427][TRACE][filewatch.readmode.handlers.readzipfile] add_new_value_sincedb_collection: /appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-1.gz {"position"=>0}
[2018-11-19T13:23:06,624][DEBUG][filewatch.sincedbcollection] writing sincedb (delta since last write = 79)
[2018-11-19T13:23:06,624][TRACE][filewatch.sincedbcollection] sincedb_write: to: /dev/null
[2018-11-19T13:23:06,634][TRACE][filewatch.readmode.handlers.readzipfile] handling: /appdata/logs/akme/lds.akme.com/854343/trv_jsa_346234.esw3cch_S.201811191100-1200-2.gz
[2018-11-19T13:24:25,191][DEBUG][filewatch.sincedbcollection] writing sincedb (delta since last write = 79)
[2018-11-19T13:24:25,191][TRACE][filewatch.sincedbcollection] sincedb_write: to: /dev/null
[2018-11-19T13:25:25,201][TRACE][filewatch.readmode.processor] Watched processing
[2018-11-19T13:25:25,201][TRACE][filewatch.readmode.processor] Active processing
[2018-11-19T13:26:25,202][TRACE][filewatch.readmode.processor] Watched processing
[2018-11-19T13:26:25,202][TRACE][filewatch.readmode.processor] Active processing

[xo4n]

I reckon it is related to Add versioned sincedb upgrade; use fingerprints instead of inode and/or path #79 as the issue doesn't show when files are not deleted with file_completed_action => "log" option

[xo4n]

Duplicate of #213 . Closing this