in_tail: Manage tail watchers that are `rorate_wait` state too #4334

ashie · 2023-10-31T01:21:59Z

Which issue(s) this PR fixes:
N/A (Follow up for #4327 (comment))

What this PR does / why we need it:
After a tail watcher transitions to rotate_wait state, the rotate_wait timer is no longer managed by in_tail, it might cause unexpected behaviour. e.g.)

It's never unwatched when shutdown occurs before rotate_wait passed.
Needless rotate_wait timers are executed when it detects more rotations.

This patch fixes such unexpected behaviour.

Docs Changes:
N/A

Release Note:
in_tail: Fix tail watchers in rotate_wait state not being managed.

ashie · 2023-10-31T01:54:14Z

* It's never unwatched when shutdown occurs before `rotate_wait` passed.
* Needless `rotate_wait` timers are executed when it detects more rotations.

Although they are unexpected behaviour, probably not harmful.
So we might skip merging this patch into the next release.
This PR is just for remind & discuss this issue.

ashie · 2023-10-31T04:47:55Z

* It's never unwatched when shutdown occurs before `rotate_wait` passed.

BTW I'm suspecting that some unstable in_tail tests are caused by it.

github-actions · 2023-11-30T10:01:39Z

This PR has been automatically marked as stale because it has been open 30 days with no activity. Remove stale label or comment or this PR will be closed in 7 days

ashie · 2023-12-20T02:30:28Z

Sometimes we get an error regarding unmanaged rotated tail watchers on shutdown:

e.g.)

[error]: #0 [in_tail] closed stream
[error]: #0 /opt/fluent/lib/ruby/gems/3.2.0/gems/fluentd-1.16.3/lib/fluent/plugin/in_tail/position_file.rb:228:in `pos='
[error]: #0 /opt/fluent/lib/ruby/gems/3.2.0/gems/fluentd-1.16.3/lib/fluent/plugin/in_tail/position_file.rb:228:in `block in update_pos'
...

We should merge this fix to v1.16.

After a tail watcher transitions to `rotate_wait` state, the `rotate_wait` timer is no longer managed by in_tail, it might cause unexpected behaviour. e.g.) * It's never unwatched when shutdown occurs before `rotate_wait` passed. * Needless `rotate_wait` timers are executed when it detects more rotations. This patch fixes such unexpected behaviour. Signed-off-by: Takuro Ashie <ashie@clear-code.com>

daipom · 2024-01-24T10:26:41Z

Thanks for this fix!

It's never unwatched when shutdown occurs before rotate_wait passed.

At this point, this fix basically looks good to me.

Needless rotate_wait timers are executed when it detects more rotations.

At this point, we need more modifications.
Maybe they should be done in other PRs, but I'd like to clarify this point at this time.

I think this occurs with follow_inodes, and ~~it makes duplicate TailWatchers and handle-leak.~~

When a very fast rotation occurs, a TailWatcher in the state of rotate_wait can call update_watcher() again.
That is the issue we should be concerned about.

Without follow_inodes, this check in update_watcher() prevents the duplicate update_watcher() process.

fluentd/lib/fluent/plugin/in_tail.rb

Lines 545 to 553 in 175d866

    
           if @pf 
        
             pe_inode = pe.read_inode 
        
             target_info_from_position_entry = TargetInfo.new(path, pe_inode) 
        
             unless pe_inode == @pf[target_info_from_position_entry].read_inode 
        
               log.warn "Skip update_watcher because watcher has been already updated by other inotify event", 
        
                        path: path, inode: pe.read_inode, inode_in_pos_file: @pf[target_info_from_position_entry].read_inode 
        
               return 
        
             end 
        
           end

It is because @pf[target_info_from_position_entry].read_inode returns the inode of the current file without follow_inodes.
So, if the TailWatcher is old, those inodes do not match.

However, with follow_inodes, this check does not work, and executes update_watcher() process duplicately.

This fix will prevent duplicate timer execution for detaching.
However, it is not enough.
We have to prevent the overall duplicate update_watcher() process.
Maybe it should be done in another PR.
=> #4334 (comment)

lib/fluent/plugin/in_tail.rb

daipom · 2024-01-25T09:12:03Z

Needless rotate_wait timers are executed when it detects more rotations.

At this point, we need more modifications. Maybe they should be done in other PRs, but I'd like to clarify this point at this time.

I think this occurs with follow_inodes, and it makes duplicate TailWatchers and handle-leak.

...

However, with follow_inodes, this check does not work, and executes update_watcher() process duplicately.

This fix will prevent duplicate timer execution for detaching. However, it is not enough. We have to prevent the overall duplicate update_watcher() process. Maybe it should be done in another PR.

Hmm, I may be wrong about this.
When using follow_inodes, the following logic prevents making duplicate TailWatcher.

fluentd/lib/fluent/plugin/in_tail.rb

Lines 558 to 561 in 175d866

    
           new_position_entry = @pf[new_target_info] 
        
           # If `refresh_watcher` find the new file before, this will not be zero. 
        
           # In this case, only we have to do is detaching the current tail_watcher. 
        
           if new_position_entry.read_inode == 0

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

daipom · 2024-01-25T12:46:34Z

I have added tests for fast rotation.

lib/fluent/plugin/in_tail.rb

daipom · 2024-01-25T12:53:23Z

@ashie Can I add a commit about the points I am commenting on?

ashie · 2024-01-26T00:14:15Z

@ashie Can I add a commit about the points I am commenting on?

Of course.

Logic inside `detach_watcher()` should be independent of `rotate_wait`. Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

daipom · 2024-01-31T03:36:57Z

@ashie Can I add a commit about the points I am commenting on?

Of course.

Done.

The new tests on macOS seem to be unstable. I will check them.

daipom · 2024-01-31T07:03:59Z

The new tests are unstable on Windows or macOS.
We need to check if we need to fix these tests or if in_tail on Windows or macOS can not collect files that are rotated very fast.

daipom · 2024-03-07T07:43:01Z

I'm sorry for the interval.
I'm checking again on the new tests on Windows and macOS.

daipom · 2024-03-07T09:49:22Z

I will merge this if it is confirmed that the newly added tests are stable.
Please let me know if anyone has concerns.

daipom · 2024-03-07T23:46:20Z

The new tests are now stable.
However, I have noticed that we need to consider rotate_wait 0 case.

daipom · 2024-03-08T01:27:59Z

However, I have noticed that we need to consider rotate_wait 0 case.

I am concerned about the possibility of the key being deleted before the key is added.
Although I can't confirm such a behavior, I have added the countermeasure just in case.

8b15478

daipom · 2024-03-08T01:29:09Z

However, I have noticed that we need to consider rotate_wait 0 case.

I am concerned about the possibility of the key being deleted before the key is added. Although I can't confirm such a behavior, I have added the countermeasure just in case.

8b15478

@ashie
Could you briefly check this?

lib/fluent/plugin/in_tail.rb

daipom · 2024-03-08T05:54:34Z

I will remove this fix, and check the following codes as well.

https://github.com/fluent/fluentd/pull/4334/files#diff-456fdeb51bc472beb48891caac0d063e0073655dba7ac2b72e6fdc67dc6ac802R272-R275

The callbacks of timers are not called after the Stop phase.
So we don't need these codes.
I will simplify those codes too.

Note: The callbacks of timers are not called after stop

fluentd/lib/fluent/plugin_helper/timer.rb

Lines 36 to 38 in c56f91e

    
           checker = ->(){ @_timer_running } 
        
           detacher = ->(watcher){ event_loop_detach(watcher) } 
        
           timer = TimerWatcher.new(title, interval, repeat, log, checker, detacher, &block)

fluentd/lib/fluent/plugin_helper/timer.rb

Lines 58 to 61 in c56f91e

    
           def stop 
        
             super 
        
             @_timer_running = false 
        
           end

fluentd/lib/fluent/plugin_helper/timer.rb

Line 80 in c56f91e

@callback.call if @checker.call

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

The comments was added in 76f246a. At that time, closing was done by event-loop. Now, the situation is completely different. Currently, there are comments about the `close_io` option in `shutdown()` and `close()`. So, it would be enough to remove these comments. Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

`sleep 1s` is too short for `enable_stat_watcher false`. Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

daipom · 2024-03-08T06:01:44Z

The code for conflicts with timer execution is unnecessary, so I have removed them.
@ashie Thanks and sorry I overlooked this.

ashie

LGTM
(It seems that I can't change the status of this pull request, because it's originally mine 🤪)

daipom · 2024-03-08T08:48:25Z

Thanks! I will merge this soon!

After a tail watcher transitions to `rotate_wait` state, the `rotate_wait` timer is no longer managed by in_tail, it might cause unexpected behaviour. e.g.) * It's never unwatched when shutdown occurs before `rotate_wait` passed. * Needless `rotate_wait` timers are executed when it detects more rotations. This patch fixes such unexpected behaviour. Note: The comment about `detach_watcher` was added in 76f246a. At that time, closing was done by event-loop. Now, the situation is completely different, so it should be removed. --------- Signed-off-by: Takuro Ashie <ashie@clear-code.com> Co-authored-by: Daijiro Fukuda <fukuda@clear-code.com>

Backport (v1.16): in_tail: Manage tail watchers that are `rorate_wait` state too (#4334)

ashie force-pushed the in-tail-manage-rotate-wait branch from 0840433 to 99af9a0 Compare October 31, 2023 01:29

ashie force-pushed the in-tail-manage-rotate-wait branch from 99af9a0 to 49e5420 Compare October 31, 2023 01:58

ashie force-pushed the in-tail-manage-rotate-wait branch 2 times, most recently from 13b91bd to 94e867b Compare October 31, 2023 05:21

github-actions bot added the stale label Nov 30, 2023

daipom added bug and removed stale labels Nov 30, 2023

ashie added this to the v1.16.4 milestone Dec 20, 2023

ashie marked this pull request as ready for review December 20, 2023 02:30

ashie changed the title ~~in_tail: Manage tail watchers under rorate_wait state~~ in_tail: Manage tail watchers that are rorate_wait state too Dec 20, 2023

ashie force-pushed the in-tail-manage-rotate-wait branch from 94e867b to 9663478 Compare January 12, 2024 04:36

ashie force-pushed the in-tail-manage-rotate-wait branch from 9663478 to ab81c16 Compare January 16, 2024 05:35

daipom self-requested a review January 24, 2024 10:01

daipom reviewed Jan 24, 2024

View reviewed changes

lib/fluent/plugin/in_tail.rb Outdated Show resolved Hide resolved

daipom reviewed Jan 25, 2024

View reviewed changes

lib/fluent/plugin/in_tail.rb Outdated Show resolved Hide resolved

in_tail: Add test for fast rotation

441b38b

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

daipom reviewed Jan 25, 2024

View reviewed changes

lib/fluent/plugin/in_tail.rb Outdated Show resolved Hide resolved

in_tail: Make deletion be done on the timer callback side

341d8b8

Logic inside `detach_watcher()` should be independent of `rotate_wait`. Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

ashie commented Mar 8, 2024

View reviewed changes

lib/fluent/plugin/in_tail.rb Outdated Show resolved Hide resolved

daipom force-pushed the in-tail-manage-rotate-wait branch from 8b15478 to f1f7866 Compare March 8, 2024 05:26

daipom added 3 commits March 8, 2024 14:58

in_tail: Make closing io handler be done in closing phase

b8315c7

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

in_tail: Make the new tests stable

d28f32e

`sleep 1s` is too short for `enable_stat_watcher false`. Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

daipom force-pushed the in-tail-manage-rotate-wait branch from f1f7866 to d28f32e Compare March 8, 2024 05:59

ashie commented Mar 8, 2024

View reviewed changes

daipom approved these changes Mar 8, 2024

View reviewed changes

daipom merged commit 83273e0 into master Mar 8, 2024
16 checks passed

daipom deleted the in-tail-manage-rotate-wait branch March 8, 2024 09:53

daipom mentioned this pull request Mar 8, 2024

Backport (v1.16): in_tail: Manage tail watchers that are rorate_wait state too (#4334) #4427

Merged

ashie added a commit that referenced this pull request Mar 11, 2024

Merge pull request #4427 from fluent/v1.16-backport-4334

0d2cd95

Backport (v1.16): in_tail: Manage tail watchers that are `rorate_wait` state too (#4334)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

in_tail: Manage tail watchers that are `rorate_wait` state too #4334

in_tail: Manage tail watchers that are `rorate_wait` state too #4334

ashie commented Oct 31, 2023 •

edited by daipom

ashie commented Oct 31, 2023 •

edited

ashie commented Oct 31, 2023

github-actions bot commented Nov 30, 2023

ashie commented Dec 20, 2023 •

edited

daipom commented Jan 24, 2024 •

edited

daipom commented Jan 25, 2024

daipom commented Jan 25, 2024

daipom commented Jan 25, 2024

ashie commented Jan 26, 2024

daipom commented Jan 31, 2024

daipom commented Jan 31, 2024

daipom commented Mar 7, 2024

daipom commented Mar 7, 2024

daipom commented Mar 7, 2024

daipom commented Mar 8, 2024

daipom commented Mar 8, 2024

daipom commented Mar 8, 2024 •

edited

daipom commented Mar 8, 2024

ashie left a comment

daipom commented Mar 8, 2024

in_tail: Manage tail watchers that are rorate_wait state too #4334

in_tail: Manage tail watchers that are rorate_wait state too #4334

Conversation

ashie commented Oct 31, 2023 • edited by daipom

ashie commented Oct 31, 2023 • edited

ashie commented Oct 31, 2023

github-actions bot commented Nov 30, 2023

ashie commented Dec 20, 2023 • edited

daipom commented Jan 24, 2024 • edited

daipom commented Jan 25, 2024

daipom commented Jan 25, 2024

daipom commented Jan 25, 2024

ashie commented Jan 26, 2024

daipom commented Jan 31, 2024

daipom commented Jan 31, 2024

daipom commented Mar 7, 2024

daipom commented Mar 7, 2024

daipom commented Mar 7, 2024

daipom commented Mar 8, 2024

daipom commented Mar 8, 2024

daipom commented Mar 8, 2024 • edited

daipom commented Mar 8, 2024

ashie left a comment

Choose a reason for hiding this comment

daipom commented Mar 8, 2024

in_tail: Manage tail watchers that are `rorate_wait` state too #4334

in_tail: Manage tail watchers that are `rorate_wait` state too #4334

ashie commented Oct 31, 2023 •

edited by daipom

ashie commented Oct 31, 2023 •

edited

ashie commented Dec 20, 2023 •

edited

daipom commented Jan 24, 2024 •

edited

daipom commented Mar 8, 2024 •

edited