SinceDB not updated properly with logstash-input-file(4.1.3)

[Tsukiand]

I have use logstash 5.6.9 with logstash-input-file(4.1.3) And we just ingest data from /var/log/audit/*.log. But i found that logstash cpu usage up to 90%. I checked with the output events and there are many repeated events.

Environment: 
CentOS 6
2vCore
500M Heap Size

Configuration:
input {
	file {
		add_field => { "component" => "sss" }
		add_field => { "svrtype" => "ssvr" }
		type => "syslog"
		exclude => [ "*.gz", "*.gzip" , "*.bzip" , "*.bzip2" ]
                path => [ "/var/log/audit/*.log" ]
		start_position => "end"
	}
}

I have no filter and just output to files.

SinceDB: I have checked the sincedb file and i found that sincedb not updated when log rotate. First,i have a file audit.log with inode numeber 655414. I get the sinceDB file.
655414 0 2054 6291832 1536236943.678 /var/log/audit/audit.log
After log rotated. audit.log change to audit.log.1 with same inode number 655414 and new audit.log with inode number 655416. But sincedb not updated to the new log state. I get the sincedb file.
655414 0 2054 6291832 1536236958.220 /var/log/audit/audit.log

I have check the output file i found that logstash ingest audit.log.1 repeatedly making the events rate up to 10k per second.Then i check the source code. I think it is the shrink process making the file offset to zero and ingest the same log in the audit.log.1
And i have check why the sincedb was not updated. I found the code in discoverer.rb which cause the the issue. If our log rotate, it will not update the sincedb with proper inode and log path. And i try to add code to fix this for myself(bold fonts). I do not know whether it is a bug. Maybe i am use logstash in a wrong way. Please give me some advice.

>    discoverer.rb
def discover_files(path)
      globbed = Dir.glob(path)
      globbed = [path] if globbed.empty?
      logger.debug("Discoverer found files, count: #{globbed.size}")
      globbed.each do |file|
        logger.debug("Discoverer found file, path: #{file}")
        pathname = Pathname.new(file)
        next unless pathname.file?
        next if pathname.symlink?
        new_discovery = false
        watched_file = @watched_files_collection.watched_file_by_path(file)
        if watched_file.nil?
          logger.debug("Discoverer discover_files: #{path}: new: #{file} (exclude is #{@exclude.inspect})")
          new_discovery = true
          watched_file = WatchedFile.new(pathname, pathname.stat, @settings)
        **elsif watched_file.sincedb_key != File.stat(file).ino
          @watched_files_collection.delete(file)
          @sincedb_collection.delete(watched_file.sincedb_key)
          new_discovery = true
          watched_file = WatchedFile.new(pathname, pathname.stat, @settings)**
        end

[guyboertje]

@Tsukiand

This is unusual given the exact glob pattern you give path => [ "/var/log/audit/*.log" ].
The file at path /var/log/audit/audit.log.1 should not be discovered at all.

irb(main):001:0> Dir.glob("/elastic/tmp/logstash-6.2.4/logs/*.log")
=> ["/elastic/tmp/logstash-6.2.4/logs/logstash-plain.log", "/elastic/tmp/logstash-6.2.4/logs/logstash-slowlog-plain.log"]
irb(main):002:0> Dir.glob("/elastic/tmp/logstash-6.2.4/logs/*.log").size
=> 2
irb(main):003:0> Dir.glob("/elastic/tmp/logstash-6.2.4/logs/*.log*").size
=> 30

However, because changes are tracked by inode after a file is discovered, the content renamed from audit.log to audit.log.1 is still tracked until close_older expires on that content.

That said, in the code reorganisation during the change from 4.0.X to 4.1.X, some handling of renamed (rotated) files was messed up. This was fixed in 4.1.4 with this PR #192.

It is quite tricky to handle these cases because the rename happens asynchronously to the loop which checks the stat of the path because the path changes. Ideally we want to be able to do a stat on the inode but this is not reliable across all OS that LS supports. There is a small time window between the rename to audit.log.1 and a new empty file audit.log being created - if a stat on audit.log occurs in this time window then the path can be flagged as "deleted".

There is a long standing understanding in our team about the problems with using paths or inodes to track changes in content because the path can change or the inode can be reused by the OS or the NFS mount is remounted with different device ids - so none of these mechanisms can uniquely identify content whether that content is a stream or a fixed written chunk. We regard file based content as streaming when the content pointed to by a path grows and then shrinks to (near) zero and grows again. We have discussed the use of one-way non crypto hashes (fingerprints) taken on fixed size chunks at known offsets as a better mechanism to identify content uniquely because when the path or inode changes we can say, via fingerprinting, that we have seen this content before and react appropriately. Fingerprinting is complex and we want to coordinate with Filebeat so we use similar algorithms etc.

[Tsukiand]

@guyboertje

Thank you for your reply. I just upgrade logstash-input-file to 4.1.4. I am testing the plugin now.

I also want to know whether logstash lost data during rotate. And i also found issue that report the data loss : #151 I want to know whether logstash fix this issue. Or we just need to use filebeat.

[guyboertje]

@Tsukiand
Was data lost? Possibly, yes - more likely duplicated.
Have we fixed it? We think so. We have put in a bunch of tests that do async rename of files and verify that the tracking is correct and no data was reread or missed but we can't create the permutations of setup that exists in the real world.

[Tsukiand]

@guyboertje
Got it! I have test myself and i found that logstash will not lose data in file rotate. Thank you for your help!

[guyboertje]

Closing. Fixed with 4.1.4 or later.

[moulisea]

@Tsukiand - I face similar issue. I have raised #279.