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.

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

in_tail: add warning for silent stop on !follow_inodes case #4339

Merged
merged 1 commit into from
Nov 10, 2023

Conversation

daipom
Copy link
Contributor

@daipom daipom commented Nov 9, 2023

Which issue(s) this PR fixes:
This PR just adds a warning log for the following issue's !follow_inodes case.

I believe this problem has been resolved with the next PR.

This PR adds a warning log just in case in order to prevent silent collection stops like that.

What this PR does / why we need it:
For refresh_watcher, if an exisiting TailWatcher already follows a target path with a different inode, it means that the TailWatcher following the rotated file still exists.

In this case, refresh_watcher can't start the new TailWatcher for the new current file.
So, we should output a warning log in order to prevent silent collection stops, such as #4327.

The warning log example:

Could not follow a file (inode: 101584481) because an existing watcher for that filepath
follows a different inode: 101584480 (e.g. keeps watching a already rotated file).
If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log"

A similar warning may work for follow_inodes too. Just limiting the case to suppress the impact to existing logic.

Docs Changes:
Not needed. (This adds a warning log only.)

Release Note:
Same as the title.

@daipom daipom added the bug label Nov 9, 2023
@daipom daipom added this to the v1.16.3 milestone Nov 9, 2023
@daipom
Copy link
Contributor Author

daipom commented Nov 9, 2023

If reverting #4327 and reproducing #3614, Fluentd outputs the following logs.

2023-11-10 08:20:59 +0900 [info]: #0 fluent/log.rb:362:info: detected rotation of /test/fluentd/input4/test.log; waiting 5 seconds
2023-11-10 08:20:59 +0900 [info]: #0 fluent/log.rb:362:info: following tail of /test/fluentd/input4/test.log
2023-11-10 08:20:59.276009558 +0900 test: {"message":"aaa"}
2023-11-10 08:20:59.480580739 +0900 test: {"message":"foo"}
2023-11-10 08:21:00.484049606 +0900 test: {"message":"foo"}
2023-11-10 08:21:01.487598040 +0900 test: {"message":"foo"}
2023-11-10 08:21:02.491227841 +0900 test: {"message":"foo"}
2023-11-10 08:21:03.494664049 +0900 test: {"message":"foo"}
2023-11-10 08:21:03 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 08:21:04.498259386 +0900 test: {"message":"foo"}
2023-11-10 08:21:05.501824361 +0900 test: {"message":"foo"}
2023-11-10 08:21:06.505372942 +0900 test: {"message":"foo"}
2023-11-10 08:21:07 +0900 [info]: #0 fluent/log.rb:362:info: detected rotation of /test/fluentd/input4/test.log; waiting 5 seconds
2023-11-10 08:21:07 +0900 [warn]: #0 fluent/log.rb:383:warn: Skip update_watcher because watcher has been already updated by other inotify event path="/test/fluentd/input4/test.log" inode=101584455 inode_in_pos_file=0
2023-11-10 08:21:13 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 08:21:13 +0900 [warn]: #0 fluent/log.rb:383:warn: Could not follow a file because an existing watcher follows the different file (inode). If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log" inode=101584480 existing_inode=101584455
2023-11-10 08:21:23 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 08:21:23 +0900 [warn]: #0 fluent/log.rb:383:warn: Could not follow a file because an existing watcher follows the different file (inode). If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log" inode=101584480 existing_inode=101584455
2023-11-10 08:21:33 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 08:21:33 +0900 [warn]: #0 fluent/log.rb:383:warn: Could not follow a file because an existing watcher follows the different file (inode). If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log" inode=101584480 existing_inode=101584455

conf

<system>
  log_level debug
</system>

<source>
  @type tail
  tag test
  path /test/fluentd/input4/test.log
  pos_file /test/fluentd/pos/pos
  read_from_head true
  refresh_interval 10
  <parse>
    @type none
  </parse>
</source>

<match test.**>
  @type stdout
</match>

@daipom daipom requested a review from kenhys November 10, 2023 02:01
@ashie ashie self-requested a review November 10, 2023 05:03
Copy link
Member

@ashie ashie left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I got it, it seems reasonable.

For `refresh_watcher`, if an exisiting TailWatcher already
follows a target path with the different inode, it means that
the TailWatcher following the rotated file still exists.

In this case, `refresh_watcher` can't start the new TailWatcher
for the new current file.
So, we should output a warning log in order to prevent silent
collection stops, such as fluent#4327.

The similar warning may work for follow_inodes too.
Just limiting the case to suppress the impact to existing logic.

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>
@daipom daipom force-pushed the in_tail-add-warning-for-silent-stop branch from b622010 to d49cfba Compare November 10, 2023 05:59
@daipom
Copy link
Contributor Author

daipom commented Nov 10, 2023

The fixed message example (old: #4339 (comment))

2023-11-10 14:56:48 +0900 [info]: #0 fluent/log.rb:362:info: detected rotation of /test/fluentd/input4/test.log; waiting 5 seconds
2023-11-10 14:56:48 +0900 [info]: #0 fluent/log.rb:362:info: following tail of /test/fluentd/input4/test.log
2023-11-10 14:56:48.355641918 +0900 test: {"message":"aaa"}
2023-11-10 14:56:48.359470882 +0900 test: {"message":"foo"}
2023-11-10 14:56:49.361542995 +0900 test: {"message":"foo"}
2023-11-10 14:56:50.365331647 +0900 test: {"message":"foo"}
2023-11-10 14:56:51.369635278 +0900 test: {"message":"foo"}
2023-11-10 14:56:52.373733110 +0900 test: {"message":"foo"}
2023-11-10 14:56:53.377578050 +0900 test: {"message":"foo"}
2023-11-10 14:56:54.381483406 +0900 test: {"message":"foo"}
2023-11-10 14:56:55.384613635 +0900 test: {"message":"foo"}
2023-11-10 14:56:56 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 14:56:56.385753030 +0900 test: {"message":"foo"}
2023-11-10 14:56:57.387629180 +0900 test: {"message":"foo"}
2023-11-10 14:56:58.393369764 +0900 test: {"message":"foo"}
2023-11-10 14:56:59 +0900 [info]: #0 fluent/log.rb:362:info: detected rotation of /test/fluentd/input4/test.log; waiting 5 seconds
2023-11-10 14:56:59 +0900 [warn]: #0 fluent/log.rb:383:warn: Skip update_watcher because watcher has been already updated by other inotify event path="/test/fluentd/input4/test.log" inode=101584480 inode_in_pos_file=0
2023-11-10 14:57:06 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 14:57:06 +0900 [warn]: #0 fluent/log.rb:383:warn: Could not follow a file (inode: 101584481) because an existing watcher for that filepath follows a different inode: 101584480 (e.g. keeps watching a already rotated file). If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log"
2023-11-10 14:57:16 +0900 [debug]: #0 fluent/log.rb:341:debug: tailing paths: target = /test/fluentd/input4/test.log | existing = /test/fluentd/input4/test.log
2023-11-10 14:57:16 +0900 [warn]: #0 fluent/log.rb:383:warn: Could not follow a file (inode: 101584481) because an existing watcher for that filepath follows a different inode: 101584480 (e.g. keeps watching a already rotated file). If you keep getting this message, please restart Fluentd. filepath="/test/fluentd/input4/test.log"

Copy link
Contributor

@kenhys kenhys left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM.

@daipom daipom merged commit dd045d3 into fluent:master Nov 10, 2023
11 of 16 checks passed
@daipom daipom deleted the in_tail-add-warning-for-silent-stop branch November 10, 2023 06:41
@daipom
Copy link
Contributor Author

daipom commented Nov 10, 2023

@kenhys @ashie Thanks!

daipom added a commit to daipom/fluentd that referenced this pull request Nov 10, 2023
)

For `refresh_watcher`, if an exisiting TailWatcher already
follows a target path with the different inode, it means that
the TailWatcher following the rotated file still exists.

In this case, `refresh_watcher` can't start the new TailWatcher
for the new current file.
So, we should output a warning log in order to prevent silent
collection stops, such as fluent#4327.

The similar warning may work for follow_inodes too.
Just limiting the case to suppress the impact to existing logic.

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants