Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

CI: Flaky "test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait" test #4707

Closed
Watson1978 opened this issue Nov 16, 2024 · 4 comments · Fixed by #4710
Closed

CI: Flaky "test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait" test #4707

Watson1978 opened this issue Nov 16, 2024 · 4 comments · Fixed by #4710
Assignees
@Watson1978
Labels
CI Test/CI issues

Comments

@Watson1978
Copy link
Contributor

Describe the bug

Sometimes, test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait will be failed

3) Failure: test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait(TailInputTest::Update watchers for rotation without follow_inodes)
D:/a/fluentd/fluentd/test/plugin/test_in_tail.rb:3358:in `test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait'
     3355:         end
     3356:       end
     3357: 
  => 3358:       assert_equal(
     3359:         {
     3360:           record_values: ["file1 log1", "file1 log2", "file2 log1", "file2 log2", "file3 log1", "file3 log2"],
     3361:           tail_watcher_paths: ["#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0"],
<{:position_entries=>
  [["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
    "0000000000000016",
    nil]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[4728759779328, 4737349320704, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
   "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
   "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0"]}> expected but was
<{:position_entries=>
  [["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
    "0000000000000016",
    4741644025856]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[4728759779328, 4737349320704, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
   "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
   "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0"]}>
diff:
  {:position_entries=>
    [["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
      "0000000000000016",
?     nil          ]],
?     4741644025856   
?     ???   
   :record_values=>
    ["file1 log1",
     "file1 log2",
     "file2 log1",
     "file2 log2",
     "file3 log1",
     "file3 log2"],
   :tail_watcher_inodes=>[4728759779328, 4737349320704, nil],
   :tail_watcher_io_handler_opened_statuses=>[false, false, false],
   :tail_watcher_paths=>
    ["D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
     "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0",
     "D:/a/fluentd/fluentd/test/plugin/../tmp/tail/0f6319cbb74ae1cd5cae/tail.txt0"]}

To Reproduce

Run CI

Expected behavior

No errors

Your Environment

- Fluentd version:
- Package version:
- Operating system:
- Kernel version:

Your Configuration

none

Your Error Log

See above

Additional context

No response
@Watson1978 Watson1978 added CI Test/CI issues and removed waiting-for-triage labels Nov 16, 2024
@Watson1978
Copy link
Contributor Author

To debug, I added the following debug code.

diff --git a/lib/fluent/plugin/in_tail/position_file.rb b/lib/fluent/plugin/in_tail/position_file.rb
index fb524a9c..8e6515d6 100644
--- a/lib/fluent/plugin/in_tail/position_file.rb
+++ b/lib/fluent/plugin/in_tail/position_file.rb
@@ -264,6 +264,16 @@ def read_inode
       end
     end
 
-    TargetInfo = Struct.new(:path, :ino)
+    TargetInfo = Struct.new(:path, :ino) do
+      def initialize(path, ino)
+        super
+        puts "[DEBUG] TargetInfo.new: path=#{path.inspect}, ino=#{ino.inspect}"
+        if ino.nil?
+          pp caller.take(20)
+        end
+        @path = path
+        @ino = ino
+      end
+    end
   end
 end
$ bundle exec ruby -Ilib:test test/plugin/test_in_tail.rb -v --testcase='TailInputTest::Update watchers for rotation without follow_inodes' --name='test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait'
Loaded suite test/plugin/test_in_tail
Started
TailInputTest: 
  Update watchers for rotation without follow_inodes: 
    test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait:

[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644632
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644632
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644632
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644637
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644632
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=21644637
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=nil
["/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:596:in `new'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:596:in `update_watcher'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:986:in `call'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:986:in `on_rotate'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:1337:in `on_notify'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:910:in `on_notify'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:472:in `block in setup_watcher'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:829:in `on_change'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/cool.io-1.9.0/lib/cool.io/loop.rb:88:in `run_once'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/cool.io-1.9.0/lib/cool.io/loop.rb:88:in `run'",
 "/home/watson/src/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'",
 "/home/watson/src/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'"]
[DEBUG] TargetInfo.new: path="test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0", ino=nil
["/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:397:in `new'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:397:in `block in existence_path'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:393:in `each'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:393:in `existence_path'",
 "/home/watson/src/fluentd/lib/fluent/plugin/in_tail.rb:281:in `shutdown'",
 "/home/watson/src/fluentd/lib/fluent/test/driver/base.rb:161:in `block in instance_shutdown'",
 "/home/watson/src/fluentd/lib/fluent/test/driver/base.rb:150:in `block in instance_shutdown'",
 "/home/watson/src/fluentd/lib/fluent/test/driver/base.rb:161:in `instance_shutdown'",
 "/home/watson/src/fluentd/lib/fluent/test/driver/base.rb:100:in `run'",
 "/home/watson/src/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'",
 "test/plugin/test_in_tail.rb:3324:in `test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:871:in `run_test'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:566:in `block (2 levels) in run'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:257:in `run_fixture'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:292:in `run_setup'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:564:in `block in run'",
 "/home/watson/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `catch'"]
F
============================================================================================================================================================================================================
Failure: test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait(TailInputTest::Update watchers for rotation without follow_inodes)
test/plugin/test_in_tail.rb:3359:in `test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait'
     3356:         end
     3357:       end
     3358: 
  => 3359:       assert_equal(
     3360:         {
     3361:           record_values: ["file1 log1", "file1 log2", "file2 log1", "file2 log2", "file3 log1", "file3 log2"],
     3362:           tail_watcher_paths: ["#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0"],
<{:position_entries=>
  [["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
    "0000000000000016",
    nil]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[21644632, 21644637, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
   "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
   "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0"]}> expected but was
<{:position_entries=>
  [["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
    "0000000000000016",
    21644639]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[21644632, 21644637, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
   "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
   "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0"]}>

diff:
  {:position_entries=>
    [["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
      "0000000000000016",
?     nil     ]],
?     21644639   
?     ???   
   :record_values=>
    ["file1 log1",
     "file1 log2",
     "file2 log1",
     "file2 log2",
     "file3 log1",
     "file3 log2"],
   :tail_watcher_inodes=>[21644632, 21644637, nil],
   :tail_watcher_io_handler_opened_statuses=>[false, false, false],
   :tail_watcher_paths=>
    ["test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
     "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0",
     "test/plugin/../tmp/tail/81e54a405de2c751998c/tail.txt0"]}
============================================================================================================================================================================================================
: (7.136332)

Finished in 7.136519377 seconds.
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
1 tests, 1 assertions, 1 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
0% passed
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
0.14 tests/s, 0.14 assertions/s
rake aborted!
Command failed with status (1): [bundle exec ruby -Ilib:test test/plugin/test_in_tail.rb -v --testcase='TailInputTest::Update watchers for rotation without follow_inodes' --name='test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait']
/home/watson/src/fluentd/runner.rake:4:in `block (2 levels) in <top (required)>'
/home/watson/src/fluentd/runner.rake:2:in `block in <top (required)>'
Tasks: TOP => default
(See full trace by running task with --trace)

@Watson1978
Copy link
Contributor Author

Seems the test will be failed when nil value is passed into 3rd argument in @update_watcher.call.

fluentd/lib/fluent/plugin/in_tail.rb

Line 986 in eebc7e1

@update_watcher.call(self, swap_state(@pe), stat&.ino)

@Watson1978 Watson1978 self-assigned this Nov 18, 2024
@Watson1978
Copy link
Contributor Author

Seems tail_watchers[2]&.ino might have nil by file rotation at sometimes.

fluentd/test/plugin/test_in_tail.rb

Line 3348 in eebc7e1

inode_2 = tail_watchers[2]&.ino

Seems it is not reflected in its attributes when update inode by file rotation.

Seems to be possible to know the inode recorded in the pos_file by referring to tail_watchers[2]&.pe&.read_inode.

@Watson1978
Copy link
Contributor Author

I think the following error is similar to this issue.

4) Failure: test_refreshTW_during_rotation(TailInputTest::Update watchers for rotation without follow_inodes)
/home/runner/work/fluentd/fluentd/test/plugin/test_in_tail.rb:3277:in `test_refreshTW_during_rotation'
     3274:         end
     3275:       end
     3276: 
  => 3277:       assert_equal(
     3278:         {
     3279:           record_values: ["file1 log1", "file1 log2", "file2 log1", "file2 log2", "file3 log1", "file3 log2"],
     3280:           tail_watcher_paths: ["#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0", "#{@tmp_dir}/tail.txt0"],
<{:position_entries=>
  [["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
    "0000000000000016",
    nil]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[519526, 519528, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
   "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
   "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0"]}> expected but was
<{:position_entries=>
  [["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
    "0000000000000016",
    519529]],
 :record_values=>
  ["file1 log1",
   "file1 log2",
   "file2 log1",
   "file2 log2",
   "file3 log1",
   "file3 log2"],
 :tail_watcher_inodes=>[519526, 519528, nil],
 :tail_watcher_io_handler_opened_statuses=>[false, false, false],
 :tail_watcher_paths=>
  ["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
   "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
   "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0"]}>

diff:
  {:position_entries=>
    [["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
      "0000000000000016",
?     nil   ]],
?     519529   
?     ???   
   :record_values=>
    ["file1 log1",
     "file1 log2",
     "file2 log1",
     "file2 log2",
     "file3 log1",
     "file3 log2"],
   :tail_watcher_inodes=>[519526, 519528, nil],
   :tail_watcher_io_handler_opened_statuses=>[false, false, false],
   :tail_watcher_paths=>
    ["/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
     "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0",
     "/home/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/a577ba09b0f4262af18e/tail.txt0"]}

@Watson1978 Watson1978 mentioned this issue Nov 19, 2024
Merged
@github-project-automation github-project-automation bot moved this from Work-In-Progress to Done in Fluentd Kanban Nov 20, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Watson1978 Watson1978

Labels
CI Test/CI issues
Projects
Fluentd Kanban
Status: Done
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

test_in_tail: fix flaky tests for file rotation Watson1978/fluentd
1 participant
@Watson1978