Add better support for file rotation #192

guyboertje · 2018-05-24T13:36:53Z

TIL The difference in Ruby between IO#stat and IO.stat, former takes a stat on the io (file) object and the latter takes a stat on a path string (as does File::Stat.new and Pathname#stat).

When an open file is rotated the watched_file path may be pointing at a different inode with new content, and if so, the opened file is still pointing to the original inode and content. We have used IO.stat or File::Stat.new (since 2012) on the path regardless of whether the file is open or closed - this is not ideal.

This PR adds the ability to do path based stat on closed files and path plus io based stat on open files. By incrementing pending_inode_count when we detect inode changes between the two kinds of stat calls and we also cache the previous size of the old content and the new content.
When the inode is different between the two stat structures we know that the file is rotated. When we detect this we can fully read the old content as we still have an open file handle. At the end of the full read we close the file io and reset the watched_file and sincedb.
NOTE: we do detect inode changes for watched_files that are not active (i.e. closed, ignored, watched) but we can't know the renamed path of the old content in order to read any content we may not have processed while the watched_file was not active. A WARN message is logged in this case. In practice this only likely to occur on not active files when tailing more than 4095 (or max_open_files if set) files AND the file is rotated before active files can be put into the closed state - files become eligible for close when the last read was more thanclose_older ago AND the file is fully read to the last stat size.
Handle race conditions better:

stat is taken bang in the middle of the rotation rename cascade, f -> f.1 | stat | tmp -> f
Discover finds the renamed path before the delete reaction can be done (this only occurs when the renamed path is inside the path glob pattern- rare).

Most of this code has been tested by a discuss user who had problems with rotations.

Fixes #188

guyboertje · 2018-05-29T15:07:08Z

I am not sure about Windows and io.stat. I need to test.

guyboertje · 2018-05-29T21:53:27Z

@colinsurprenant
Please suspend review, half of this code is useless under Windows.
I need to circle back. 🤠 🔴 🚶

colinsurprenant · 2018-05-30T15:33:45Z

lib/filewatch/discoverer.rb

          new_discovery = true
          watched_file = WatchedFile.new(pathname, pathname.stat, @settings)
+          logger.debug("Discoverer new discovery: #{watched_file.path}, inode: #{watched_file.sincedb_key.inode}, discover_files: #{path} (exclude is #{@exclude.inspect})")


minor: you are using the structured logs notations in most places, maybe here too?

I started to change the logging to structured but its a PR all of its own.

colinsurprenant · 2018-05-30T15:37:41Z

I just did a shallow review and changes LGTM. I haven't run the tests nor tried to more deeply analyse because there are lots of changes and complexity is high. I will trust your testing and spec coverage.
Just a really minor comment about the debug logging format.

colinsurprenant · 2018-05-30T15:54:56Z

@guyboertje ah damn ... I did not see your last comment before starting. oh well.

guyboertje · 2018-06-01T14:45:13Z

After some investigation in GCP on a Windows Server 2008 box I now know:

Currently we hold the file open for 1 hour (AND the file must be fully read) unless the use specified a different close_older.
JRuby reports increases in size when doing a stat on the IO object.
Windows does not allow renaming or deleting a file when an open file handle exists - so no rotation is possible until we close the file (we don't have burning fires on this).
In Windows the stat struct returned by either path or io based method always has the inode at 0 - this is not good and the reason we have the FFI functions in winhelper.rb.
I am looking into a mechanism that can get the windows inode equivalent for a path and io using JRuby jnr. If successful then most of this PR will not need to change.

to better handle when a file is rotated that has never been active. Change the way @previous_inode_size is cached, it needs to be set only when an inode change is detected. Change discover associate behaviour if the matched watched_file is open. Add spec for when a file is rotated that has never been active. Alter specs because we can rely on ordering with "file_sort_by"

…s PR

especially in the case where the rotated files are discoverable - in this case we were not the moving the state and the sincedb record correctly. Next - abstract the *nix and Windows stat calls and structure into two classes with the same API.

Move all tail processing state iteration into its own method Clean up rspec sequencing usage. Remove all Mutex use in favour of AtomicBoolean, AtomicArray, AtomicHash Add wait for completely_stopped before removing sincedb in file_tail spec

guyboertje · 2018-06-29T15:25:11Z

Arrrrrggghhhhhhh!!!! @£$%$%$
(J)Ruby IO stat

So I backed out the IO stat code. Now travis is green, biggest yay evar!

Now to run the tests on Windows to make sure the windows execution path is not broken.

@colinsurprenant Nearly there.

guyboertje · 2018-07-02T14:55:28Z

@colinsurprenant
Please resume reviewing.

colinsurprenant · 2018-07-05T16:11:20Z

ci/unit/Dockerfile

+ENV LOGSTASH_SOURCE 1
+RUN jruby -S gem install bundler
+RUN jruby -S bundle install --jobs=3 --retry=3
+RUN jruby -S bundle exec rake vendor


shouldn't we be using Gradle ? also why is this needed here?

This is copied from @jsvd work after the jruby S3 bucket went AWOL on the weekend.
Behind the scenes it does use gradle so I suppose we could run gradle here.
I don't want to touch it now, it works, we can circle back after confirming with Joao about this. It is a pattern we need to apply to all (most) plugins - probably scripted.

Step 11/11 : RUN jruby -S bundle exec rake vendor ---> Running in a4c0913880da Downloading https://services.gradle.org/distributions/gradle-4.5.1-bin.zip ..................................................................... Unzipping /usr/share/logstash/.gradle/wrapper/dists/gradle-4.5.1-bin/a5vbgfvpwtoqz8v2cdivxz28k/gradle-4.5.1-bin.zip to /usr/share/logstash/.gradle/wrapper/dists/gradle-4.5.1-bin/a5vbgfvpwtoqz8v2cdivxz28k Set executable permissions for: /usr/share/logstash/.gradle/wrapper/dists/gradle-4.5.1-bin/a5vbgfvpwtoqz8v2cdivxz28k/gradle-4.5.1/bin/gradle Starting a Gradle Daemon (subsequent builds will be faster) :cleanGemjar UP-TO-DATE :clean UP-TO-DATE :compileJava Download https://repo.maven.apache.org/maven2/org/jruby/jruby-complete/9.1.13.0/jruby-complete-9.1.13.0.pom Download https://repo.maven.apache.org/maven2/org/jruby/jruby-artifacts/9.1.13.0/jruby-artifacts-9.1.13.0.pom Download https://repo.maven.apache.org/maven2/org/jruby/jruby-parent/9.1.13.0/jruby-parent-9.1.13.0.pom Download https://repo.maven.apache.org/maven2/org/sonatype/oss/oss-parent/7/oss-parent-7.pom Download https://repo.maven.apache.org/maven2/org/jruby/jruby-complete/9.1.13.0/jruby-complete-9.1.13.0.jar :processResources NO-SOURCE :classes :jar :sourcesJar :copyGemjar

ok I see.
I just created elastic/logstash/issues/9823 - we can move that discussion over there (or open a specific issue about it and link it there)

colinsurprenant · 2018-07-05T17:04:47Z

lib/filewatch/bootstrap.rb

  require "java"
-  require_relative "../../lib/jars/filewatch-#{jar_version}.jar"
+  fullpath = gem_root_dir.join("lib/jars/filewatch-#{jar_version}.jar").expand_path.to_path


shouldn't we rely on jar-dependencies to load this jar file? I believe this is what filter-date does to load its own compiles jar?

Will look but TBH jar-dependencies is so opaque/obscure to me that I think it is fine for external deps from maven but I trust the current mechanism more.

colinsurprenant · 2018-07-05T17:12:31Z

spec/helpers/logging_level_helper.rb

@@ -0,0 +1,8 @@
+# encoding: utf-8
+
+ENV["LOG_AT"].tap do |level|


is this documented somewhere so that future devs know about this if useful?

Not really. I suppose it should be in devutils but until now I have been reluctant to make changes in that direction.
It is useful in this plugin with --fail-fast and trace logging to see what is going on. Before, the tests might fail in the suite but not when run individually.
I am not sure how useful it is to other plugins that don't have extensive trace logging.

sure - please don't touch devutils if only for getting rid of it. What I was saying is that since this could be useful to other developers that will work on this plugin and will need to run tests, it could be documented somewhere like a local CONTRIBUTING file or unsure where else but the idea is that if it can be useful to other, they must know about it in some way?

I understand now. I will add something when building the final changelog PR.

colinsurprenant · 2018-07-05T17:18:04Z

Same disclaimer: for the exception of a few minor comments, given the amount and complexity of the changes this is shallow review LGTM and I will rely on @guyboertje extensive testing.

guyboertje · 2018-07-05T18:01:39Z

Ok. I'm going to squash merge this.

fbaligand · 2018-07-05T19:22:15Z

Great news @guyboertje !
Could you release it ?

guyboertje added the needs reviewing label May 24, 2018

guyboertje requested a review from colinsurprenant May 25, 2018 19:51

guyboertje self-assigned this May 25, 2018

colinsurprenant reviewed May 30, 2018

View reviewed changes

colinsurprenant approved these changes May 30, 2018

View reviewed changes

Guy Boertje added 8 commits June 19, 2018 10:16

Add better support for file rotation

7622fc7

Ensure single file path option is ok, reverts earlier change in thi…

60ab865

…s PR

Improve and expand our use of FFI on Windows

fb48cc5

jnr and ffi interop, yay

f0720e1

put self back in

f25c2b1

use fieldId label

fb4ae28

handle rotations better.

2c846d3

especially in the case where the rotated files are discoverable - in this case we were not the moving the state and the sincedb record correctly. Next - abstract the *nix and Windows stat calls and structure into two classes with the same API.

guyboertje force-pushed the fix/rotation branch from dd5dfa5 to 2c846d3 Compare June 19, 2018 09:21

Guy Boertje added 10 commits June 19, 2018 11:16

fixes for rebase from master

f2b8555

Abstract Stat part 1

fe96100

Abstract Stat part 2

d127aa0

Finally have (all) the kinks worked out

58a2518

Try to fix travis failures.

124e318

Try to fix travis failures 2

05498b4

Try fix travis 3

487c641

Try fix travis 4

167eecf

Try fix travis 5

6c82057

Try fix travis 6

168f451

sv-gh mentioned this pull request Jun 27, 2018

#189 Zero byte read from NFS - Fix method file_read in watched_file.rb #190

Closed

guyboertje mentioned this pull request Jun 29, 2018

v4.1 : regression - new files are not detected by plugin #198

Closed

Guy Boertje added 9 commits June 30, 2018 22:25

Some windows fixes

ab409ed

more windows fixes

a176a35

windows changes 2

62dccf8

rename rspec run tag in ci/build.sh

8504125

move one trace logging line

6e36c89

add first run discovery methods

ff3bb5a

fix regression on files seen after inital run, travis 2 use docker.

ac62656

add execute permissions

257687e

fix path ordering travis failures

ee0855b

fix jar loading so it works for tests and when installed in LS

a86893e

colinsurprenant reviewed Jul 5, 2018

View reviewed changes

reorder the jar require statements

242bad3

colinsurprenant reviewed Jul 5, 2018

View reviewed changes

colinsurprenant mentioned this pull request Jul 5, 2018

WIP: Better support for NFS, step 1 #199

Merged

guyboertje merged commit 498eb5e into logstash-plugins:master Jul 5, 2018

guyboertje deleted the fix/rotation branch July 5, 2018 18:05

guyboertje mentioned this pull request Sep 7, 2018

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

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add better support for file rotation #192

Add better support for file rotation #192

guyboertje commented May 24, 2018 •

edited

Loading

guyboertje commented May 29, 2018

guyboertje commented May 29, 2018

colinsurprenant May 30, 2018

guyboertje May 30, 2018

colinsurprenant commented May 30, 2018

colinsurprenant commented May 30, 2018

guyboertje commented Jun 1, 2018

guyboertje commented Jun 29, 2018 •

edited

Loading

guyboertje commented Jul 2, 2018

colinsurprenant Jul 5, 2018

guyboertje Jul 5, 2018

colinsurprenant Jul 5, 2018

colinsurprenant Jul 5, 2018

guyboertje Jul 5, 2018

colinsurprenant Jul 5, 2018

guyboertje Jul 5, 2018

colinsurprenant Jul 5, 2018

guyboertje Jul 5, 2018

colinsurprenant commented Jul 5, 2018

guyboertje commented Jul 5, 2018

fbaligand commented Jul 5, 2018

		@@ -0,0 +1,8 @@
		# encoding: utf-8

		ENV["LOG_AT"].tap do \|level\|

Add better support for file rotation #192

Add better support for file rotation #192

Conversation

guyboertje commented May 24, 2018 • edited Loading

guyboertje commented May 29, 2018

guyboertje commented May 29, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

colinsurprenant commented May 30, 2018

colinsurprenant commented May 30, 2018

guyboertje commented Jun 1, 2018

guyboertje commented Jun 29, 2018 • edited Loading

guyboertje commented Jul 2, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

colinsurprenant commented Jul 5, 2018

guyboertje commented Jul 5, 2018

fbaligand commented Jul 5, 2018

guyboertje commented May 24, 2018 •

edited

Loading

guyboertje commented Jun 29, 2018 •

edited

Loading