search

fluent / fluentd

Fluentd: Unified Logging Layer (project under CNCF)
https://www.fluentd.org
Apache License 2.0
12.91k stars 1.34k forks source link

CI: Flaky "test_next_rotation_occurs_very_fast_while_old_TW_still_waiting_rotate_wait" test #4707

Open Watson1978 opened 2 hours ago

Watson1978 commented 2 hours ago

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 commented 2 hours ago

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 commented 2 hours ago

Seems the test will be failed when nil value is passed into 3rd argument in @update_watcher.call. https://github.com/fluent/fluentd/blob/eebc7e1da6e0916be2ccdfab79fe0cffef296d21/lib/fluent/plugin/in_tail.rb#L986