Refactor logger initialization #4065

daipom · 2023-02-19T18:56:26Z

Which issue(s) this PR fixes:
I found this problem during fixing:

Logger: Log format setting is not applied to the first log #4037 (comment)

This fix should be done before fixing this issue.

What this PR does / why we need it:
In the supervisor process, Fluentd initializes the logger twice, at Supervisor::configure() and Supervisor.load_config().

Supervisor.load_config() is called in ServerEngine's reloading function, but Fluentd doesn't use the function even when SIGHUP or SIGUSR2.
So I can't see the reason for initializing the logger in that callback.

This also fixes a problem that ignore_same_log_interval is not passed to the Supervisor.load_config() and that option is not reflected to the logger of the supervisor process.

Docs Changes:
Not needed.

Release Note:

Fix bug that ignore_same_log_interval option is not reflected in the supervisor process.
Fix bug that suppress_repeated_stacktrace from SystemConfig is not reflected in the worker processes.

We should consider the release note with

Fix problem that some system configs are not reflected #4064

In the supervisor process, Fluentd initializes the logger twice, at `Supervisor::configure()` and `Supervisor.load_config()`. `Supervisor.load_config()` is called in ServerEngine's reloading function, but Fluentd doesn't use the function even when `SIGHUP` or `SIGUSR2`. So I can't see the reason for initializing the logger in the callback. In addition, I removed some needless parameters that were passed to ServerEngine. This also fixes a problem that `ignore_same_log_interval` is not passed to the `Supervisor.load_config()` and that option is not reflected to the logger of the supervisor process. Signed-off-by: Daijiro Fukuda <[email protected]>

daipom · 2023-03-03T04:21:41Z

I rebased this to apply #4064.

Please tell me if we need to investigate more about ServerEngine's reloading function.
If so, I will summarize Fluentd and ServerEngine's behavior related to this.

daipom · 2023-03-03T04:59:27Z

I am concerned that the Ruby 2.7 on macos-latest test fails.

https://github.com/fluent/fluentd/actions/runs/4320183945/jobs/7540167787

 Failure: test_unwatched_files_should_be_removed(TailInputTest::path)
/Users/runner/work/fluentd/fluentd/test/plugin/test_in_tail.rb:1616:in `test_unwatched_files_should_be_removed'
     1613:       waiting(20) { sleep 0.1 until Dir.glob("#{@tmp_dir}/*.txt").size == 0 } # Ensure file is deleted on Windows
     1614:       waiting(5) { sleep 0.1 until d.instance.instance_variable_get(:@tails).keys.size <= 0 }
     1615: 
  => 1616:       assert_equal(
     1617:         {
     1618:           files: [],
     1619:           tails: []
<{:files=>[], :tails=>[]}> expected but was
<{:files=>[],
 :tails=>
  ["/Users/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/dcebe801d2a39d7ba0fc/tail.txt"]}>

diff:
? {:files=>[], :tails=>[]}
+  :tails=>
+   ["/Users/runner/work/fluentd/fluentd/test/plugin/../tmp/tail/dcebe801d2a39d7ba0fc/tail.txt"]}

ashie · 2023-03-03T05:03:30Z

It's a known unstable test.
We should make it stable but not related with this change.

daipom · 2023-03-03T05:13:17Z

It's a known unstable test. We should make it stable but not related with this change.

Thanks, I have created the issue:

CI: The test_unwatched_files_should_be_removed test fails sometimes #4079

ashie · 2023-03-03T08:55:31Z

This also fixes a problem that ignore_same_log_interval is not passed to the Supervisor.load_config() and that option is not reflected to the logger of the supervisor process.

You mean suppress_repeated_stacktrace?
According to your commit, the addressed parameter seems suppress_repeated_stacktrace, not ignore_same_log_interval.

ashie · 2023-03-03T08:58:46Z

Supervisor.load_config() is called in ServerEngine's reloading function, but Fluentd doesn't use the function even when SIGHUP or SIGUSR2. So I can't see the reason for initializing the logger in that callback.

Sorry, I can't remember the code around it soon.
I'm sorry to bother you but could you point out the rationale?

daipom · 2023-03-03T10:35:33Z

This also fixes a problem that ignore_same_log_interval is not passed to the Supervisor.load_config() and that option is not reflected to the logger of the supervisor process.

You mean suppress_repeated_stacktrace? According to your commit, the addressed parameter seems suppress_repeated_stacktrace, not ignore_same_log_interval.

No. Originally, ignore_same_log_interval is not passed here.

fluentd/lib/fluent/supervisor.rb

Lines 870 to 896 in e58fd66

    
           params = { 
        
             'main_cmd' => fluentd_spawn_cmd, 
        
             'daemonize' => @daemonize, 
        
             'inline_config' => @inline_config, 
        
             'log_path' => @log_path, 
        
             'log_rotate_age' => @log_rotate_age, 
        
             'log_rotate_size' => @log_rotate_size, 
        
             'chuser' => @chuser, 
        
             'chgroup' => @chgroup, 
        
             'use_v1_config' => @use_v1_config, 
        
             'conf_encoding' => @conf_encoding, 
        
             'signame' => @signame, 
        
             'fluentd_conf' => @conf.to_s, 
        
             'workers' => @system_config.workers, 
        
             'root_dir' => @system_config.root_dir, 
        
             'log_level' => @system_config.log_level, 
        
             'suppress_repeated_stacktrace' => @system_config.suppress_repeated_stacktrace, 
        
             'ignore_repeated_log_interval' => @system_config.ignore_repeated_log_interval, 
        
             'rpc_endpoint' => @system_config.rpc_endpoint, 
        
             'enable_get_dump' => @system_config.enable_get_dump, 
        
             'counter_server' => @system_config.counter_server, 
        
             'log_format' => @system_config.log.format, 
        
             'log_time_format' => @system_config.log.time_format, 
        
             'disable_shared_socket' => @system_config.disable_shared_socket, 
        
             'restart_worker_interval' => @system_config.restart_worker_interval, 
        
           }

So Fluent::Log::ignore_same_log_interval is always nil after Supervisor.load_config()

fluentd/lib/fluent/supervisor.rb

Line 442 in e58fd66

ignore_same_log_interval = params['ignore_same_log_interval']

fluentd/lib/fluent/supervisor.rb

Lines 451 to 457 in e58fd66

    
           log_opts = {suppress_repeated_stacktrace: suppress_repeated_stacktrace, ignore_repeated_log_interval: ignore_repeated_log_interval, 
        
                       ignore_same_log_interval: ignore_same_log_interval} 
        
           logger_initializer = Supervisor::LoggerInitializer.new( 
        
             log_path, log_level, chuser, chgroup, log_opts, 
        
             log_rotate_age: log_rotate_age, 
        
             log_rotate_size: log_rotate_size 
        
           )

daipom · 2023-03-03T10:35:40Z

The reason why I fixed the codes about suppress_repeated_stacktrace is that originally the suppress_repeated_stacktrace value from the SytemConfig was applied in Supervisor.load_config().

fluentd/lib/fluent/supervisor.rb

Line 887 in e58fd66

'suppress_repeated_stacktrace' => @system_config.suppress_repeated_stacktrace,

Since this PR removes the initialization process of the logger from Supervisor.load_config(), now we need to apply the suppress_repeated_stacktrace value from the SytemConfig in here.

fluentd/lib/fluent/supervisor.rb

Lines 820 to 826 in e58fd66

    
           @log.apply_options( 
        
             format: @system_config.log.format, 
        
             time_format: @system_config.log.time_format, 
        
             log_dir_perm: @system_config.dir_permission, 
        
             ignore_repeated_log_interval: @system_config.ignore_repeated_log_interval, 
        
             ignore_same_log_interval: @system_config.ignore_same_log_interval 
        
           )

Note: The following logic applies the suppress_repeated_stacktrace value from the command line options.

fluentd/lib/fluent/supervisor.rb

Lines 699 to 705 in e58fd66

    
           log_opts = {suppress_repeated_stacktrace: opt[:suppress_repeated_stacktrace], ignore_repeated_log_interval: opt[:ignore_repeated_log_interval], 
        
                       ignore_same_log_interval: opt[:ignore_same_log_interval]} 
        
           @log = LoggerInitializer.new( 
        
             @log_path, opt[:log_level], @chuser, @chgroup, log_opts, 
        
             log_rotate_age: @log_rotate_age, 
        
             log_rotate_size: @log_rotate_size 
        
           )

daipom · 2023-03-03T10:40:50Z

Thus, I thought I didn't change the specification of suppress_repeated_stacktrace,,, but now I'm concerned about if suppress_repeated_stacktrace of a worker process has been changed...
(Originally, was it applied to a worker process correctly??)
I will look into this.

daipom · 2023-03-03T10:43:03Z

Supervisor.load_config() is called in ServerEngine's reloading function, but Fluentd doesn't use the function even when SIGHUP or SIGUSR2. So I can't see the reason for initializing the logger in that callback.

Sorry, I can't remember the code around it soon. I'm sorry to bother you but could you point out the rationale?

Sure! Me too, sorry for the lack of explanation.
I will add more explanation about this.

daipom · 2023-03-08T08:42:45Z

Supervisor.load_config() is called in ServerEngine's reloading function, but Fluentd doesn't use the function even when SIGHUP or SIGUSR2. So I can't see the reason for initializing the logger in that callback.

Sorry, I can't remember the code around it soon. I'm sorry to bother you but could you point out the rationale?

Sure! Me too, sorry for the lack of explanation. I will add more explanation about this.

About ServerEngine logic

Initialization of Daemon
- Supervisor.load_config() of Fluentd is called at this initialization process.
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/daemon.rb#L32
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/config_loader.rb#L23-L37
ConfigLoader::reload_config()
- The question is whether this can be called outside of initialization.
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/config_loader.rb#L42-L58
Server::restart() or Server::reload() are the trigger for ConfigLoader::reload_config().
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/server.rb#L59-L71
They can be called by SIGNAL.
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/server.rb#L78-L116
- USR1, USR2, HUP

Fluentd supervisor process overwrite all these SIGNALs, and does NOT use this ServerEngine feature.

fluentd/lib/fluent/supervisor.rb

Lines 176 to 193 in 248160f

    
           def install_supervisor_signal_handlers 
        
             return if Fluent.windows? 
        
             trap :HUP do 
        
               $log.debug "fluentd supervisor process get SIGHUP" 
        
               supervisor_sighup_handler 
        
             end 
        
             trap :USR1 do 
        
               $log.debug "fluentd supervisor process get SIGUSR1" 
        
               supervisor_sigusr1_handler 
        
             end 
        
             trap :USR2 do 
        
               $log.debug 'fluentd supervisor process got SIGUSR2' 
        
               supervisor_sigusr2_handler 
        
             end 
        
           end

I'll check the Windows just to be sure.

daipom · 2023-03-08T09:12:36Z

On Windows, Fluentd overwrites Server::restart() and Server:reload(), so it does NOT use ConfigLoader::reload_config().

fluentd/lib/fluent/supervisor.rb

Lines 195 to 211 in 248160f

    
           if Fluent.windows? 
        
             # Override some methods of ServerEngine::MultiSpawnWorker 
        
             # Since Fluentd's Supervisor doesn't use ServerEngine's HUP, USR1 and USR2 
        
             # handlers (see install_supervisor_signal_handlers), they should be 
        
             # disabled also on Windows, just send commands to workers instead. 
        
             def restart(graceful) 
        
               @monitors.each do |m| 
        
                 m.send_command(graceful ? "GRACEFUL_RESTART\n" : "IMMEDIATE_RESTART\n") 
        
               end 
        
             end 
        
             def reload 
        
               @monitors.each do |m| 
        
                 m.send_command("RELOAD\n") 
        
               end 
        
             end 
        
           end

daipom · 2023-03-08T09:16:06Z

On Ubuntu focal, I have confirmed that sending USR1, USR2, HUP to the supervisor process does not call Supervisor.load_config().

On Windows, I have confirmed that using fluent-ctl flush/restart/reload to the supervisor process does not call it.

daipom · 2023-03-08T09:21:12Z

I'm checking the history...

daipom · 2023-03-08T09:37:19Z

It seems that Supervisor.load_config() is used by USR2 and HUP at the point of #880, but after #2716, Fluentd completely stopped using ServerEngine's reload_config() feature. (I'm not sure about Windows specification at this point.)

After #2716, there seems to be no longer any need to initialize the logger in Supervisor.load_config().

daipom · 2023-03-08T09:52:09Z

I tried Fluentd v1.8.1, which does not include #2716, and I confirmed that sending USR2 to the supervisor process call Supervisor.load_config().

From the above, I conclude as follows.

Supervisor.load_config() was used for reloading, but not anymore. (since Reload new config without restarting process #2716)
- Therefore, in the past, we could update the logger on reloading by initializing it there, but now it is meaningless.
So currently Supervisor.load_config() is only for the initialization of ServerEngine.
Supervisor and worker process of Fluentd have their own logger for their process, so all Fluentd has to do about logging in Supervisor.load_config() is passing its logger to ServerEnigne.
- Then ServerEnigne just uses it.
- https://github.com/treasure-data/serverengine/blob/v2.3.1/lib/serverengine/config_loader.rb#L62-L68

daipom · 2023-03-08T10:16:09Z

Thus, I thought I didn't change the specification of suppress_repeated_stacktrace,,, but now I'm concerned about if suppress_repeated_stacktrace of a worker process has been changed... (Originally, was it applied to a worker process correctly??) I will look into this.

I have checked this.
Surprisingly, suppress_repeated_stacktrace of SystemConfig was not applied to worker processes...
This PR fixes it too.

About suppress_repeated_stacktrace from SystemConfig:

Before Fix problem that some system configs are not reflected #4064, suppress_repeated_stacktrace from SystemConfig is not applied to the supervisor and workers.
Fix problem that some system configs are not reflected #4064 fixes it so that it is applied to the supervisor correctly.
This PR fixed it so that it is applied to the workers correctly.

daipom · 2023-03-08T10:23:22Z

I have organized all the information.
If you need more detailed information, please let me know.

ashie

Thanks for your detailed explanation! I've understood the issue.
It looks good to me.
I've added a nitpick comment in lines.

lib/fluent/supervisor.rb

Signed-off-by: Daijiro Fukuda <[email protected]>

It is hard to understand what is this method and how it works. Signed-off-by: Daijiro Fukuda <[email protected]>

daipom · 2023-03-09T01:52:36Z

lib/fluent/supervisor.rb

+    # For ServerEngine's `reload_config`.
+    # This is called only at the initilization of the supervisor process,
+    # since Fluentd overwrites all related SIGNAL(HUP,USR1,USR2) and have own
+    # reloading feature.
    def self.load_config(path, params = {})


Perhaps we should rename or move this method.
It is hard to understand what this method is.
I will do it in another PR.

ashie · 2023-03-09T02:50:46Z

Thanks!

daipom · 2023-03-09T02:51:21Z

Thanks for your review!

daipom marked this pull request as draft February 21, 2023 14:28

daipom mentioned this pull request Feb 27, 2023

Proposing a new Fluentd maintainer #4069

Merged

daipom force-pushed the refactor-logger-initialization branch from 39c6698 to afee4a4 Compare March 3, 2023 04:15

daipom changed the title ~~Draft: Refactor logger initialization~~ Refactor logger initialization Mar 3, 2023

daipom marked this pull request as ready for review March 3, 2023 04:16

daipom requested a review from ashie March 3, 2023 04:21

ashie added this to the v1.16.0 milestone Mar 3, 2023

daipom mentioned this pull request Mar 8, 2023

Fix problem that some system configs are not reflected #4064

Merged

ashie reviewed Mar 9, 2023

View reviewed changes

lib/fluent/supervisor.rb Outdated Show resolved Hide resolved

daipom added 2 commits March 9, 2023 10:37

Remove needless local variables

e793a51

Signed-off-by: Daijiro Fukuda <[email protected]>

Add comment for Supervisor.load_config()

6b74fa3

It is hard to understand what is this method and how it works. Signed-off-by: Daijiro Fukuda <[email protected]>

daipom commented Mar 9, 2023

View reviewed changes

ashie approved these changes Mar 9, 2023

View reviewed changes

ashie merged commit 7b0e0cd into fluent:master Mar 9, 2023

daipom deleted the refactor-logger-initialization branch March 9, 2023 02:51

daipom mentioned this pull request Mar 9, 2023

Refactor Superviser.load_config() #4086

Merged

kenhys mentioned this pull request Sep 5, 2023

-p overwrites the default plugin path #4269

Closed

daipom mentioned this pull request Mar 11, 2024

Windows: cannot launch Fluentd with --daemon #4354

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refactor logger initialization #4065

Refactor logger initialization #4065

daipom commented Feb 19, 2023 •

edited

Loading

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

ashie commented Mar 3, 2023

daipom commented Mar 3, 2023

ashie commented Mar 3, 2023

ashie commented Mar 3, 2023 •

edited

Loading

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023

daipom commented Mar 8, 2023

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023

ashie left a comment

daipom Mar 9, 2023

ashie commented Mar 9, 2023

daipom commented Mar 9, 2023

Refactor logger initialization #4065

Refactor logger initialization #4065

Conversation

daipom commented Feb 19, 2023 • edited Loading

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

ashie commented Mar 3, 2023

daipom commented Mar 3, 2023

ashie commented Mar 3, 2023

ashie commented Mar 3, 2023 • edited Loading

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 3, 2023

daipom commented Mar 8, 2023 • edited Loading

About ServerEngine logic

daipom commented Mar 8, 2023

daipom commented Mar 8, 2023

daipom commented Mar 8, 2023 • edited Loading

daipom commented Mar 8, 2023 • edited Loading

daipom commented Mar 8, 2023 • edited Loading

daipom commented Mar 8, 2023 • edited Loading

daipom commented Mar 8, 2023

ashie left a comment

Choose a reason for hiding this comment

daipom Mar 9, 2023

Choose a reason for hiding this comment

ashie commented Mar 9, 2023

daipom commented Mar 9, 2023

daipom commented Feb 19, 2023 •

edited

Loading

ashie commented Mar 3, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading

daipom commented Mar 8, 2023 •

edited

Loading