Logger: Log format setting is not applied to the first log

[daipom]

Describe the bug

I noticed this issue when I was checking #4011.

The log of initializing logger is added in Fluentd v1.15.3 at #3939:
Fluentd outputs this log first.

2023-02-03 19:24:28 +0900 [info]: fluent/log.rb:330:info: init supervisor logger path=nil rotate_age=nil rotate_size=nil

However, the log format is not applied to this log.

• https://github.com/fluent/fluentd/blob/v1.15.3/lib/fluent/supervisor.rb#L451-L452
• https://github.com/fluent/fluentd/blob/v1.15.3/lib/fluent/supervisor.rb#L586

At the point of LoggerInitializer::init(), the format is not applied yet, so the logger must not output logs.

To Reproduce

Run Fluentd v1.15.3 by the following config and see the first log.

$ bundle exec fluentd -c /path/to/fluent.conf

Expected behavior

Log format setting is applied to the all logs of Fluentd.

Your Environment

• Fluentd version: v1.15.3
• Operating system:

  $ cat /etc/os-release
  NAME="Ubuntu"
  VERSION="20.04.5 LTS (Focal Fossa)"
  ID=ubuntu
  ID_LIKE=debian
  PRETTY_NAME="Ubuntu 20.04.5 LTS"
  VERSION_ID="20.04"
  HOME_URL="https://www.ubuntu.com/"
  SUPPORT_URL="https://help.ubuntu.com/"
  BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
  PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
  VERSION_CODENAME=focal
  UBUNTU_CODENAME=focal

• Kernel version:

  $ uname -r
  5.15.0-58-generic

Your Configuration

<system>
  <log>
    format json
    time_format %Y-%m-%dT%H:%M:%S%z
  </log>
</system>

<source>
  @type sample
  tag test
</source>

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

Your Error Log

2023-02-03 19:24:28 +0900 [info]: fluent/log.rb:330:info: init supervisor logger path=nil rotate_age=nil rotate_size=nil
{"time":"2023-02-03T19:24:28+0900","level":"info","message":"parsing config file is succeeded path=\"../work/fluent.conf\""}
{"time":"2023-02-03T19:24:28+0900","level":"info","message":"gem 'fluentd' version '1.15.3'"}
...

Additional context

No response

[daipom]

I will fix this.

[daipom]

I'm trying to fix this, but I have some questions about the initialization of the logger.

Why does the supervisor process initialize the logger in Supervisor.load_config()?

fluentd/lib/fluent/supervisor.rb

Lines 443 to 453 in e89092c

	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
	)
	# this #init sets initialized logger to $log
	logger_initializer.init(:supervisor, 0)
	logger_initializer.apply_options(format: params['log_format'], time_format: params['log_time_format'])
	logger = $log

Fluentd passes the function as a callback to ServerEngine.

fluentd/lib/fluent/supervisor.rb

Lines 898 to 900 in e89092c

	se = ServerEngine.create(ServerModule, WorkerModule){
	Fluent::Supervisor.load_config(@config_path, params)
	}

I have checked the related codes of ServerEngine, but I can't see the reason for initializing the logger in the callback.

I thought it might have something to do with the function of reloading the config, such as SIGUSR2, but that doesn't seem to be true.

I'm going to look into this a little more, but it appears that the logger settings are determined at point Supervisor::configure().

fluentd/lib/fluent/supervisor.rb

Lines 810 to 826 in e89092c

	@conf = Fluent::Config.build(
	config_path: @config_path,
	encoding: @conf_encoding,
	additional_config: @inline_config,
	use_v1_config: @use_v1_config,
	type: @config_file_type,
	)
	@system_config = build_system_config(@conf)
	@log.level = @system_config.log_level
	@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
	)

I think we should limit the initialization point to Supervisor::configure().

(I understand the logger must be initialized temporarily in order to output some logs before parsing the config.
This is why the logger initialization is separated into Supervisor::initialize() and Supervisor::configure().
But I can't see the reason for it in the Supervisor.load_config() too.)