From f8b73a571954b4a7cfb137cb521edeb370f3f0b5 Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Tue, 14 Mar 2023 17:28:57 +0900 Subject: [PATCH 1/9] Fix logger initialization The logic of initializing logger is so difficult and has caused many bugs. This fix simplifies it and prevents logger from outputting some initial log messages with some settings not applied, such as `format`. This fix consists of the following 2 points. * All logger parameters are now set in the first initialization. * Previously, only parameters related to rotation were applied first, but it is preferable to apply all parameters on that point. * Remove LoggerInitializer * This class was a source of confusion because its role is difficult to understand. TODO: Fix tests. Signed-off-by: Daijiro Fukuda --- lib/fluent/log.rb | 37 +++++- lib/fluent/supervisor.rb | 252 ++++++++++++++++----------------------- 2 files changed, 136 insertions(+), 153 deletions(-) diff --git a/lib/fluent/log.rb b/lib/fluent/log.rb index e574947c3b..f9ecc82b43 100644 --- a/lib/fluent/log.rb +++ b/lib/fluent/log.rb @@ -67,8 +67,29 @@ def self.event_tags LEVEL_TEXT.map{|t| "#{LOG_EVENT_TAG_PREFIX}.#{t}" } end + # Create a unique path for each process. + # + # >>> per_process_path("C:/tmp/test.log", :worker, 1) + # C:/tmp/test-1.log + # >>> per_process_path("C:/tmp/test.log", :supervisor, 0) + # C:/tmp/test-supervisor-0.log + def self.per_process_path(path, process_type, worker_id) + path = Pathname(path) + ext = path.extname + + if process_type == :supervisor + suffix = "-#{process_type}-0#{ext}" # "-0" for backword compatibility. + else + suffix = "-#{worker_id}#{ext}" + end + return path.sub_ext(suffix).to_s + end + def initialize(logger, opts={}) - # overwrites logger.level= so that config reloading resets level of Fluentd::Log + # When ServerEngine changes the logger.level, the Fluentd logger level should also change. + # So overwrites logger.level= below. + # However, currently Fluentd doesn't use the ServerEngine's reloading feature, + # so maybe we don't need this overwriting anymore. orig_logger_level_setter = logger.class.public_instance_method(:level=).bind(logger) me = self # The original ruby logger sets the number as each log level like below. @@ -92,6 +113,7 @@ def initialize(logger, opts={}) # So if serverengine's logger level is changed, fluentd's log level will be changed to that + 1. logger.define_singleton_method(:level=) {|level| orig_logger_level_setter.call(level); me.level = self.level + 1 } + @path = opts[:path] @logger = logger @out = logger.instance_variable_get(:@logdev) @level = logger.level + 1 @@ -102,7 +124,8 @@ def initialize(logger, opts={}) @time_format = nil @formatter = nil - self.format = :text + self.format = opts.fetch(:format, :text) + self.time_format = opts[:time_format] if opts.key?(:time_format) enable_color out.tty? # TODO: This variable name is unclear so we should change to better name. @threads_exclude_events = [] @@ -156,6 +179,10 @@ def dup attr_reader :time_format attr_accessor :log_event_enabled, :ignore_repeated_log_interval, :ignore_same_log_interval, :suppress_repeated_stacktrace attr_accessor :out + # Strictly speaking, we should also change @logger.level when the setter of @level is called. + # Currently, we don't need to do it, since Fluentd::Log doesn't use ServerEngine::DaemonLogger.level. + # Since We overwrites logger.level= so that @logger.level is applied to @level, + # we need to find a good way to do this, otherwise we will end up in an endless loop. attr_accessor :level attr_accessor :optional_header, :optional_attrs @@ -202,8 +229,12 @@ def time_format=(time_fmt) @time_formatter = Strftime.new(@time_format) rescue nil end + def stdout? + @out == $stdout + end + def reopen! - @logger.reopen! if @logger + @out.reopen(@path, "a") if @path && @path != "-" nil end diff --git a/lib/fluent/supervisor.rb b/lib/fluent/supervisor.rb index 043e447f5a..2fa31f161b 100644 --- a/lib/fluent/supervisor.rb +++ b/lib/fluent/supervisor.rb @@ -362,11 +362,11 @@ def dump private def reopen_log - if (log = config[:logger_initializer]) + if $log # Creating new thread due to mutex can't lock # in main thread during trap context Thread.new do - log.reopen! + $log.reopen! end end end @@ -443,7 +443,6 @@ def self.serverengine_config(params = {}) logger: $log, log: $log.out, log_level: params['log_level'], - logger_initializer: params['logger_initializer'], chuser: params['chuser'], chgroup: params['chgroup'], chumask: params['chumask'], @@ -471,104 +470,6 @@ def self.serverengine_config(params = {}) se_config end - class LoggerInitializer - def initialize(path, level, chuser, chgroup, opts, log_rotate_age: nil, log_rotate_size: nil) - @path = path - @level = level - @chuser = chuser - @chgroup = chgroup - @opts = opts - @log_rotate_age = log_rotate_age - @log_rotate_size = log_rotate_size - end - - # Create a unique path for each process. - # - # >>> per_process_path(:worker, 1, "C:/tmp/test.log") - # C:/tmp/test-1.log - # >>> per_process_path(:supervisor, 0, "C:/tmp/test.log") - # C:/tmp/test-supervisor-0.log - def self.per_process_path(path, process_type, worker_id) - path = Pathname(path) - ext = path.extname - - if process_type == :supervisor - suffix = "-#{process_type}-0#{ext}" # "-0" for backword compatibility. - else - suffix = "-#{worker_id}#{ext}" - end - return path.sub_ext(suffix).to_s - end - - def init(process_type, worker_id) - @opts[:process_type] = process_type - @opts[:worker_id] = worker_id - - if @path && @path != "-" - unless File.exist?(@path) - FileUtils.mkdir_p(File.dirname(@path)) - end - - if @log_rotate_age || @log_rotate_size - # We need to prepare a unique path for each worker since - # Windows locks files. - @path = LoggerInitializer.per_process_path(@path, process_type, worker_id) if Fluent.windows? - @logdev = Fluent::LogDeviceIO.new(@path, shift_age: @log_rotate_age, shift_size: @log_rotate_size) - else - @logdev = File.open(@path, "a") - end - - if @chuser || @chgroup - chuid = @chuser ? ServerEngine::Privilege.get_etc_passwd(@chuser).uid : nil - chgid = @chgroup ? ServerEngine::Privilege.get_etc_group(@chgroup).gid : nil - File.chown(chuid, chgid, @path) - end - else - @logdev = STDOUT - end - - dl_opts = {} - # subtract 1 to match serverengine daemon logger side logging severity. - dl_opts[:log_level] = @level - 1 - dl_opts[:log_rotate_age] = @log_rotate_age if @log_rotate_age - dl_opts[:log_rotate_size] = @log_rotate_size if @log_rotate_size - logger = ServerEngine::DaemonLogger.new(@logdev, dl_opts) - $log = Fluent::Log.new(logger, @opts) - $log.enable_color(false) if @path - $log.enable_debug if @level <= Fluent::Log::LEVEL_DEBUG - $log.info "init #{process_type} logger", path: @path, rotate_age: @log_rotate_age, rotate_size: @log_rotate_size - end - - def stdout? - @logdev == STDOUT - end - - def reopen! - if @path && @path != "-" - @logdev.reopen(@path, "a") - end - self - end - - def apply_options(format: nil, time_format: nil, log_dir_perm: nil, - ignore_repeated_log_interval: nil, ignore_same_log_interval: nil, suppress_repeated_stacktrace: nil) - $log.format = format if format - $log.time_format = time_format if time_format - $log.ignore_repeated_log_interval = ignore_repeated_log_interval if ignore_repeated_log_interval - $log.ignore_same_log_interval = ignore_same_log_interval if ignore_same_log_interval - $log.suppress_repeated_stacktrace = suppress_repeated_stacktrace unless suppress_repeated_stacktrace.nil? - - if @path && log_dir_perm - File.chmod(log_dir_perm || Fluent::DEFAULT_DIR_PERMISSION, File.dirname(@path)) - end - end - - def level=(level) - @level = level - $log.level = level - end - end - def self.default_options { config_path: Fluent::DEFAULT_CONFIG_PATH, @@ -625,35 +526,18 @@ def initialize(cl_opt) @chgroup = opt[:chgroup] @chuser = opt[:chuser] @chumask = opt[:chumask] + @signame = opt[:signame] + # TODO: `@log_rotate_age` and `@log_rotate_size` should be removed + # since it should be merged with SystemConfig in `build_system_config()`. + # We should always use `system_config.log.rotate_age` and `system_config.log.rotate_size`. + # However, currently, there is a bug that `system_config.log` parameters + # are not in `Fluent::SystemConfig::SYSTEM_CONFIG_PARAMETERS`, and these + # parameters are not merged in `build_system_config()`. + # Until we fix the bug of `Fluent::SystemConfig`, we need to use these instance variables. @log_rotate_age = opt[:log_rotate_age] @log_rotate_size = opt[:log_rotate_size] - @signame = opt[:signame] - @conf = nil - # parse configuration immediately to initialize logger in early stage - if @config_path and File.exist?(@config_path) - @conf = Fluent::Config.build(config_path: @config_path, - encoding: @conf_encoding ? @conf_encoding : 'utf-8', - additional_config: @inline_config ? @inline_config : nil, - use_v1_config: !!@use_v1_config, - type: @config_file_type, - ) - @system_config = build_system_config(@conf) - if @system_config.log - @log_rotate_age ||= @system_config.log.rotate_age - @log_rotate_size ||= @system_config.log.rotate_size - end - @conf = nil - end - - 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 - ) @finished = false end @@ -738,17 +622,7 @@ def run_worker end def configure(supervisor: false) - if supervisor - @log.init(:supervisor, 0) - else - worker_id = ENV['SERVERENGINE_WORKER_ID'].to_i - process_type = case - when @standalone_worker then :standalone - when worker_id == 0 then :worker0 - else :workers - end - @log.init(process_type, worker_id) - end + setup_global_logger(supervisor: supervisor) if @show_plugin_config show_plugin_config @@ -767,16 +641,6 @@ def configure(supervisor: false) ) @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, - suppress_repeated_stacktrace: @system_config.suppress_repeated_stacktrace, - ) - $log.info :supervisor, 'parsing config file is succeeded', path: @config_path @libs.each do |lib| @@ -800,6 +664,90 @@ def configure(supervisor: false) private + def setup_global_logger(supervisor: false) + if supervisor + worker_id = 0 + process_type = :supervisor + else + worker_id = ENV['SERVERENGINE_WORKER_ID'].to_i + process_type = case + when @standalone_worker then :standalone + when worker_id == 0 then :worker0 + else :workers + end + end + + # Parse configuration immediately to initialize logger in early stage. + # Since we can't confirm the log messages in this parsing process, + # we must parse the config again after initializing logger. + 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) + + # TODO: we should remove this logic. This merging process should be done + # in `build_system_config()`. + @log_rotate_age ||= system_config.log.rotate_age + @log_rotate_size ||= system_config.log.rotate_size + + rotate = @log_rotate_age || @log_rotate_size + actual_log_path = @log_path + + # We need to prepare a unique path for each worker since Windows locks files. + if Fluent.windows? && rotate + actual_log_path = Fluent::Log.per_process_path(@log_path, process_type, worker_id) + end + + if actual_log_path && actual_log_path != "-" + FileUtils.mkdir_p(File.dirname(actual_log_path)) unless File.exist?(actual_log_path) + if rotate + logdev = Fluent::LogDeviceIO.new( + actual_log_path, + shift_age: @log_rotate_age, + shift_size: @log_rotate_size, + ) + else + logdev = File.open(actual_log_path, "a") + end + + if @chuser || @chgroup + chuid = @chuser ? ServerEngine::Privilege.get_etc_passwd(@chuser).uid : nil + chgid = @chgroup ? ServerEngine::Privilege.get_etc_group(@chgroup).gid : nil + File.chown(chuid, chgid, actual_log_path) + end + + if system_config.dir_permission + File.chmod(system_config.dir_permission || Fluent::DEFAULT_DIR_PERMISSION, File.dirname(actual_log_path)) + end + else + logdev = STDOUT + end + + $log = Fluent::Log.new( + # log_level: subtract 1 to match serverengine daemon logger side logging severity. + ServerEngine::DaemonLogger.new(logdev, log_level: system_config.log_level - 1), + path: actual_log_path, + process_type: process_type, + worker_id: worker_id, + format: system_config.log.format, + time_format: system_config.log.time_format, + suppress_repeated_stacktrace: system_config.suppress_repeated_stacktrace, + ignore_repeated_log_interval: system_config.ignore_repeated_log_interval, + ignore_same_log_interval: system_config.ignore_same_log_interval, + ) + $log.enable_color(false) if actual_log_path + $log.enable_debug if system_config.log_level <= Fluent::Log::LEVEL_DEBUG + + $log.info "init #{process_type} logger", + path: actual_log_path, + rotate_age: @log_rotate_age, + rotate_size: @log_rotate_size + end + def create_socket_manager socket_manager_path = ServerEngine::SocketManager::Server.generate_path ServerEngine::SocketManager::Server.open(socket_manager_path) @@ -833,7 +781,6 @@ def supervise 'workers' => @system_config.workers, 'root_dir' => @system_config.root_dir, - 'logger_initializer' => @log, 'log_level' => @system_config.log_level, 'rpc_endpoint' => @system_config.rpc_endpoint, 'enable_get_dump' => @system_config.enable_get_dump, @@ -937,7 +884,7 @@ def flush_buffer begin $log.debug "fluentd main process get SIGUSR1" $log.info "force flushing buffered events" - @log.reopen! + $log.reopen! Fluent::Engine.flush! $log.debug "flushing thread: flushed" rescue Exception => e @@ -993,7 +940,7 @@ def dump_windows def logging_with_console_output yield $log - unless @log.stdout? + unless $log.stdout? logger = ServerEngine::DaemonLogger.new(STDOUT) log = Fluent::Log.new(logger) log.level = @system_config.log_level @@ -1050,6 +997,11 @@ def main_process(&block) def build_system_config(conf) system_config = SystemConfig.create(conf, @cl_opt[:strict_config_value]) # Prefer the options explicitly specified in the command line + # + # TODO: There is a bug that `system_config.log.rotate_age/rotate_size` are + # not merged with the command line options since they are not in + # `SYSTEM_CONFIG_PARAMETERS`. + # We have to fix this bug. opt = {} Fluent::SystemConfig::SYSTEM_CONFIG_PARAMETERS.each do |param| if @cl_opt.key?(param) && !@cl_opt[param].nil? From e21fc3a1f07dd7a57f332273b53e39222c1775bb Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 22:27:57 +0900 Subject: [PATCH 2/9] Test: Refactor tests about --inline-config The previous one was almost testing nothing. Signed-off-by: Daijiro Fukuda --- test/command/test_fluentd.rb | 12 ++++++++++++ test/test_config.rb | 21 --------------------- test/test_supervisor.rb | 15 --------------- 3 files changed, 12 insertions(+), 36 deletions(-) diff --git a/test/command/test_fluentd.rb b/test/command/test_fluentd.rb index 9627d8a670..87c9d28d96 100644 --- a/test/command/test_fluentd.rb +++ b/test/command/test_fluentd.rb @@ -1270,4 +1270,16 @@ def multi_workers_ready?; true; end "[debug]") end end + + sub_test_case "inline_config" do + test "can change log_level by --inline-config" do + # Since we can't define multiple `` directives, this use-case is not recommended. + # This is just for this test. + inline_conf = '\nlog_level debug\n' + conf_path = create_conf_file('test.conf', "") + assert File.exist?(conf_path) + assert_log_matches(create_cmdline(conf_path, "--inline-config", inline_conf), + "[debug]") + end + end end diff --git a/test/test_config.rb b/test/test_config.rb index 4828d9190f..24f63830d4 100644 --- a/test/test_config.rb +++ b/test/test_config.rb @@ -344,27 +344,6 @@ def write_config(path, data, encoding: 'utf-8') File.open(path, "w:#{encoding}:utf-8") {|f| f.write data } end - def test_inline - prepare_config - opts = { - :config_path => "#{TMP_DIR}/config_test_1.conf", - :inline_config => "\n type http\n port 2222\n ", - :use_v1_config => false - } - assert_nothing_raised do - Fluent::Supervisor.new(opts) - end - create_warn_dummy_logger - end - - def create_warn_dummy_logger - dl_opts = {} - dl_opts[:log_level] = ServerEngine::DaemonLogger::WARN - logdev = Fluent::Test::DummyLogDevice.new - logger = ServerEngine::DaemonLogger.new(logdev, dl_opts) - $log = Fluent::Log.new(logger) - end - sub_test_case '.build' do test 'read config' do write_config("#{TMP_DIR}/build/config_build.conf", 'key value') diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index d2ffc2083d..936139789d 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -676,21 +676,6 @@ def test_override_default_log_rotate_with_yaml_config end end - def test_inline_config - omit 'this feature is deprecated. see https://github.com/fluent/fluentd/issues/2711' - - sv = Fluent::Supervisor.new({inline_config: '-'}) - assert_equal '-', sv.instance_variable_get(:@inline_config) - - inline_config = '\n@type stdout\n' - stub(STDIN).read { inline_config } - stub(Fluent::Config).build # to skip - stub(sv).build_system_config { Fluent::SystemConfig.new } # to skip - - sv.configure - assert_equal inline_config, sv.instance_variable_get(:@inline_config) - end - def test_log_level_affects sv = Fluent::Supervisor.new({}) From cf2abb7cee53ad8191cd9c68dd842c60f63edb7c Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 15:59:09 +0900 Subject: [PATCH 3/9] Test: Move per_process_path test Signed-off-by: Daijiro Fukuda --- test/test_log.rb | 8 ++++++++ test/test_supervisor.rb | 8 -------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/test/test_log.rb b/test/test_log.rb index 480781d4d8..3e8e4c1c35 100644 --- a/test/test_log.rb +++ b/test/test_log.rb @@ -33,6 +33,14 @@ def teardown end end + def test_per_process_path + path = Fluent::Log.per_process_path("C:/tmp/test.log", :supervisor, 0) + assert_equal(path, "C:/tmp/test-supervisor-0.log") + + path = Fluent::Log.per_process_path("C:/tmp/test.log", :worker, 1) + assert_equal(path, "C:/tmp/test-1.log") + end + sub_test_case "log level" do data( trace: [Fluent::Log::LEVEL_TRACE, 0], diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index 936139789d..d8e6ceaab4 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -717,14 +717,6 @@ def server.config end end - def test_per_process_path - path = Fluent::Supervisor::LoggerInitializer.per_process_path("C:/tmp/test.log", :supervisor, 0) - assert_equal(path, "C:/tmp/test-supervisor-0.log") - - path = Fluent::Supervisor::LoggerInitializer.per_process_path("C:/tmp/test.log", :worker, 1) - assert_equal(path, "C:/tmp/test-1.log") - end - def create_debug_dummy_logger dl_opts = {} dl_opts[:log_level] = ServerEngine::DaemonLogger::DEBUG From fd77c4354333582acbf0a8895f0f2969f04d290d Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 23:13:38 +0900 Subject: [PATCH 4/9] Test: Fix SupervisorTest * Overwritten `DamonLogger#level=` is not used now, since Fluentd doesn't use ServerEngine's reloading feature. * The parameters about rotate is in `Fluent::LogDeviceIO`, not in `ServerEngine::DaemonLogger`. Signed-off-by: Daijiro Fukuda --- test/test_supervisor.rb | 51 ++++++++++++++++++----------------------- 1 file changed, 22 insertions(+), 29 deletions(-) diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index d8e6ceaab4..3be7a46b61 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -29,6 +29,7 @@ def tmp_dir end def setup + @stored_global_logger = $log @tmp_dir = tmp_dir @tmp_root_dir = File.join(@tmp_dir, 'root') FileUtils.mkdir_p(@tmp_dir) @@ -36,6 +37,7 @@ def setup end def teardown + $log = @stored_global_logger begin FileUtils.rm_rf(@tmp_dir) rescue Errno::EACCES @@ -322,6 +324,8 @@ def test_term_cont_in_supervisor_signal_handler def test_windows_shutdown_event omit "Only for Windows platform" unless Fluent.windows? + create_debug_dummy_logger + server = DummyServer.new def server.config {:signame => "TestFluentdEvent"} @@ -591,22 +595,6 @@ def test_init_for_logger(data) assert_equal 20, $log.ignore_same_log_interval end - def test_logger - sv = Fluent::Supervisor.new({}) - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) - logger = $log.instance_variable_get(:@logger) - - assert_equal Fluent::Log::LEVEL_INFO, $log.level - - # test that DamonLogger#level= overwrites Fluent.log#level - logger.level = 'debug' - assert_equal Fluent::Log::LEVEL_DEBUG, $log.level - - assert_equal 5, logger.instance_variable_get(:@rotate_age) - assert_equal 1048576, logger.instance_variable_get(:@rotate_size) - end - data( daily_age: 'daily', weekly_age: 'weekly', @@ -614,9 +602,16 @@ def test_logger integer_age: 2, ) def test_logger_with_rotate_age_and_rotate_size(rotate_age) - sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test", log_rotate_age: rotate_age, log_rotate_size: 10}) - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) + config_path = "#{@tmp_dir}/empty.conf" + write_config config_path, "" + + sv = Fluent::Supervisor.new( + config_path: config_path, + log_path: "#{@tmp_dir}/test", + log_rotate_age: rotate_age, + log_rotate_size: 10, + ) + sv.__send__(:setup_global_logger) assert_equal Fluent::LogDeviceIO, $log.out.class assert_equal rotate_age, $log.out.instance_variable_get(:@shift_age) @@ -643,13 +638,12 @@ def test_override_default_log_rotate file.flush sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path}) - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) + sv.__send__(:setup_global_logger) logger = $log.instance_variable_get(:@logger) - assert_equal([3, 300], - [logger.instance_variable_get(:@rotate_age), - logger.instance_variable_get(:@rotate_size)]) + assert_equal Fluent::LogDeviceIO, $log.out.class + assert_equal 3, $log.out.instance_variable_get(:@shift_age) + assert_equal 300, $log.out.instance_variable_get(:@shift_size) end end @@ -665,13 +659,12 @@ def test_override_default_log_rotate_with_yaml_config file.flush sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path, config_file_type: :yaml}) - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) + sv.__send__(:setup_global_logger) logger = $log.instance_variable_get(:@logger) - assert_equal([3, 300], - [logger.instance_variable_get(:@rotate_age), - logger.instance_variable_get(:@rotate_size)]) + assert_equal Fluent::LogDeviceIO, $log.out.class + assert_equal 3, $log.out.instance_variable_get(:@shift_age) + assert_equal 300, $log.out.instance_variable_get(:@shift_size) end end end From 3ad5cd9625a4f4438d8b6a39dc9a4be48af73724 Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 16:14:40 +0900 Subject: [PATCH 5/9] Test: Fix Fluent::Config::TestSystemConfig This test should be fixed more..., but it should be done in another branch. Currently, `TestSystemConfig` tests some Supervisor logic too. This is not good, and it should be moved to SupervisorTest. We should remove `FakeSupervisor` class. Signed-off-by: Daijiro Fukuda --- test/config/test_system_config.rb | 8 -------- 1 file changed, 8 deletions(-) diff --git a/test/config/test_system_config.rb b/test/config/test_system_config.rb index 7b18cb3dd1..502fb7d75a 100644 --- a/test/config/test_system_config.rb +++ b/test/config/test_system_config.rb @@ -5,13 +5,6 @@ require 'fluent/system_config' module Fluent::Config - class FakeLoggerInitializer - attr_accessor :level - def initialize - @level = nil - end - end - class FakeSupervisor attr_writer :log_level @@ -21,7 +14,6 @@ def initialize(**opt) wokers: nil, restart_worker_interval: nil, root_dir: nil, - log: FakeLoggerInitializer.new, log_level: Fluent::Log::LEVEL_INFO, suppress_interval: nil, suppress_config_dump: nil, From 156274f73fe64dd3f973a9ad70ad1c2c7fbcb52b Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 16:58:58 +0900 Subject: [PATCH 6/9] SupervisorTest: Summarize logger tests in one sub_test Just add `sub_test_case "init logger"`. Other all diff is re-indent. Signed-off-by: Daijiro Fukuda --- test/test_supervisor.rb | 172 ++++++++++++++++++++-------------------- 1 file changed, 87 insertions(+), 85 deletions(-) diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index 3be7a46b61..18fa8d928d 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -568,11 +568,12 @@ def test_serverengine_config_for_daemonize assert_equal './fluentd.pid', se_config[:pid_path] end - data("supervisor", { supervise: true }) - data("worker", { supervise: false }) - def test_init_for_logger(data) - tmp_conf_path = "#{@tmp_dir}/dir/test_init_for_logger.conf" - conf_info_str = %[ + sub_test_case "init logger" do + data("supervisor", { supervise: true }) + data("worker", { supervise: false }) + def test_init_for_logger(data) + tmp_conf_path = "#{@tmp_dir}/dir/test_init_for_logger.conf" + conf_info_str = %[ suppress_repeated_stacktrace false ignore_repeated_log_interval 10s @@ -583,100 +584,101 @@ def test_init_for_logger(data) ] - write_config tmp_conf_path, conf_info_str + write_config tmp_conf_path, conf_info_str - s = Fluent::Supervisor.new({config_path: tmp_conf_path}) - s.configure(supervisor: data[:supervise]) + s = Fluent::Supervisor.new({config_path: tmp_conf_path}) + s.configure(supervisor: data[:supervise]) - assert_equal :json, $log.format - assert_equal '%FT%T.%L%z', $log.time_format - assert_equal false, $log.suppress_repeated_stacktrace - assert_equal 10, $log.ignore_repeated_log_interval - assert_equal 20, $log.ignore_same_log_interval - end + assert_equal :json, $log.format + assert_equal '%FT%T.%L%z', $log.time_format + assert_equal false, $log.suppress_repeated_stacktrace + assert_equal 10, $log.ignore_repeated_log_interval + assert_equal 20, $log.ignore_same_log_interval + end - data( - daily_age: 'daily', - weekly_age: 'weekly', - monthly_age: 'monthly', - integer_age: 2, - ) - def test_logger_with_rotate_age_and_rotate_size(rotate_age) - config_path = "#{@tmp_dir}/empty.conf" - write_config config_path, "" - - sv = Fluent::Supervisor.new( - config_path: config_path, - log_path: "#{@tmp_dir}/test", - log_rotate_age: rotate_age, - log_rotate_size: 10, + data( + daily_age: 'daily', + weekly_age: 'weekly', + monthly_age: 'monthly', + integer_age: 2, ) - sv.__send__(:setup_global_logger) - - assert_equal Fluent::LogDeviceIO, $log.out.class - assert_equal rotate_age, $log.out.instance_variable_get(:@shift_age) - assert_equal 10, $log.out.instance_variable_get(:@shift_size) - end - - sub_test_case "system log rotation" do - def parse_text(text) - basepath = File.expand_path(File.dirname(__FILE__) + '/../../') - Fluent::Config.parse(text, '(test)', basepath, true).elements.find { |e| e.name == 'system' } + def test_logger_with_rotate_age_and_rotate_size(rotate_age) + config_path = "#{@tmp_dir}/empty.conf" + write_config config_path, "" + + sv = Fluent::Supervisor.new( + config_path: config_path, + log_path: "#{@tmp_dir}/test", + log_rotate_age: rotate_age, + log_rotate_size: 10, + ) + sv.__send__(:setup_global_logger) + + assert_equal Fluent::LogDeviceIO, $log.out.class + assert_equal rotate_age, $log.out.instance_variable_get(:@shift_age) + assert_equal 10, $log.out.instance_variable_get(:@shift_size) end - def test_override_default_log_rotate - Tempfile.open do |file| - config = parse_text(<<-EOS) - - - rotate_age 3 - rotate_size 300 - - - EOS - file.puts(config) - file.flush - sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path}) - - sv.__send__(:setup_global_logger) - logger = $log.instance_variable_get(:@logger) - - assert_equal Fluent::LogDeviceIO, $log.out.class - assert_equal 3, $log.out.instance_variable_get(:@shift_age) - assert_equal 300, $log.out.instance_variable_get(:@shift_size) + sub_test_case "system log rotation" do + def parse_text(text) + basepath = File.expand_path(File.dirname(__FILE__) + '/../../') + Fluent::Config.parse(text, '(test)', basepath, true).elements.find { |e| e.name == 'system' } end - end - def test_override_default_log_rotate_with_yaml_config - Tempfile.open do |file| - config = <<-EOS - system: - log: - rotate_age: 3 - rotate_size: 300 - EOS - file.puts(config) - file.flush - sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path, config_file_type: :yaml}) - - sv.__send__(:setup_global_logger) - logger = $log.instance_variable_get(:@logger) + def test_override_default_log_rotate + Tempfile.open do |file| + config = parse_text(<<-EOS) + + + rotate_age 3 + rotate_size 300 + + + EOS + file.puts(config) + file.flush + sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path}) + + sv.__send__(:setup_global_logger) + logger = $log.instance_variable_get(:@logger) + + assert_equal Fluent::LogDeviceIO, $log.out.class + assert_equal 3, $log.out.instance_variable_get(:@shift_age) + assert_equal 300, $log.out.instance_variable_get(:@shift_size) + end + end - assert_equal Fluent::LogDeviceIO, $log.out.class - assert_equal 3, $log.out.instance_variable_get(:@shift_age) - assert_equal 300, $log.out.instance_variable_get(:@shift_size) + def test_override_default_log_rotate_with_yaml_config + Tempfile.open do |file| + config = <<-EOS + system: + log: + rotate_age: 3 + rotate_size: 300 + EOS + file.puts(config) + file.flush + sv = Fluent::Supervisor.new({log_path: "#{@tmp_dir}/test.log", config_path: file.path, config_file_type: :yaml}) + + sv.__send__(:setup_global_logger) + logger = $log.instance_variable_get(:@logger) + + assert_equal Fluent::LogDeviceIO, $log.out.class + assert_equal 3, $log.out.instance_variable_get(:@shift_age) + assert_equal 300, $log.out.instance_variable_get(:@shift_size) + end end end - end - def test_log_level_affects - sv = Fluent::Supervisor.new({}) + def test_log_level_affects + sv = Fluent::Supervisor.new({}) - c = Fluent::Config::Element.new('system', '', { 'log_level' => 'error' }, []) - stub(Fluent::Config).build { config_element('ROOT', '', {}, [c]) } + c = Fluent::Config::Element.new('system', '', { 'log_level' => 'error' }, []) + stub(Fluent::Config).build { config_element('ROOT', '', {}, [c]) } - sv.configure - assert_equal Fluent::Log::LEVEL_ERROR, $log.level + sv.configure + assert_equal Fluent::Log::LEVEL_ERROR, $log.level + end end def test_enable_shared_socket From f1ce1d2de0219d8d6050b903855070a45a7360ea Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 17:38:53 +0900 Subject: [PATCH 7/9] SupervisorTest: Refactor some tests Signed-off-by: Daijiro Fukuda --- test/test_supervisor.rb | 31 ++++++++++++++++--------------- 1 file changed, 16 insertions(+), 15 deletions(-) diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index 18fa8d928d..bc97c9c850 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -569,25 +569,26 @@ def test_serverengine_config_for_daemonize end sub_test_case "init logger" do - data("supervisor", { supervise: true }) - data("worker", { supervise: false }) - def test_init_for_logger(data) + data(supervisor: true) + data(worker: false) + def test_init_for_logger(supervisor) tmp_conf_path = "#{@tmp_dir}/dir/test_init_for_logger.conf" - conf_info_str = %[ - - suppress_repeated_stacktrace false - ignore_repeated_log_interval 10s - ignore_same_log_interval 20s - - format json - time_format %FT%T.%L%z - - -] + conf_info_str = <<~EOC + + log_level warn # To suppress logs + suppress_repeated_stacktrace false + ignore_repeated_log_interval 10s + ignore_same_log_interval 20s + + format json + time_format %FT%T.%L%z + + + EOC write_config tmp_conf_path, conf_info_str s = Fluent::Supervisor.new({config_path: tmp_conf_path}) - s.configure(supervisor: data[:supervise]) + s.configure(supervisor: supervisor) assert_equal :json, $log.format assert_equal '%FT%T.%L%z', $log.time_format From d909dc83b91504eb09a389df334c5681ad42e5bc Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Mon, 13 Mar 2023 00:26:53 +0900 Subject: [PATCH 8/9] Test: Move tests in LoggerInitializerTest Removed `rotate`, `rotate to max age` tests since `LogTest::test_log_rotates_specified_size_with_logdevio` already exists. Signed-off-by: Daijiro Fukuda --- test/test_log.rb | 23 ++++++ test/test_logger_initializer.rb | 120 -------------------------------- test/test_supervisor.rb | 77 ++++++++++++++++++++ 3 files changed, 100 insertions(+), 120 deletions(-) delete mode 100644 test/test_logger_initializer.rb diff --git a/test/test_log.rb b/test/test_log.rb index 3e8e4c1c35..a344b532e3 100644 --- a/test/test_log.rb +++ b/test/test_log.rb @@ -5,6 +5,7 @@ require 'timecop' require 'logger' require 'securerandom' +require 'pathname' class LogTest < Test::Unit::TestCase def tmp_dir @@ -641,6 +642,28 @@ def test_log_rotates_specified_size_with_logdevio assert_true !File.exist?(path1) end end + + def test_reopen + path = Pathname(@tmp_dir) + "fluent.log" + + logdev = Fluent::LogDeviceIO.new(path.to_s) + logger = ServerEngine::DaemonLogger.new(logdev) + log = Fluent::Log.new(logger, path: path) + + message = "This is test message." + + log.info message + log.reopen! + log.info message + + assert { path.read.lines.select{ |line| line.include?(message) }.size == 2 } + # Assert reopening the same file. + # Especially, on Windows, the filepath is fixed for each process with rotate, + # so we need to care about this. + assert { path.parent.entries.size == 3 } # [".", "..", "fluent.log"] + ensure + logdev&.close + end end class PluginLoggerTest < Test::Unit::TestCase diff --git a/test/test_logger_initializer.rb b/test/test_logger_initializer.rb deleted file mode 100644 index a476841010..0000000000 --- a/test/test_logger_initializer.rb +++ /dev/null @@ -1,120 +0,0 @@ -require_relative 'helper' -require 'fluent/supervisor' -require 'fileutils' -require 'pathname' - -class LoggerInitializerTest < ::Test::Unit::TestCase - def setup - @stored_global_logger = $log - Dir.mktmpdir do |tmp_dir| - @tmp_dir = Pathname(tmp_dir) - yield - end - end - - def teardown - $log = @stored_global_logger - end - - test 'when path is given' do - path = @tmp_dir + 'log' + 'fluent_with_path.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}) - mock.proxy(File).chmod(0o777, path.parent.to_s).never - - assert_nothing_raised do - logger.init(:supervisor, 0) - end - $log.out.close - - assert { path.parent.exist? } - end - - test 'apply_options with log_dir_perm' do - omit "NTFS doesn't support UNIX like permissions" if Fluent.windows? - - path = @tmp_dir + 'log' + 'fluent_with_path.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}) - mock.proxy(File).chmod(0o777, path.parent.to_s).once - - assert_nothing_raised do - logger.init(:supervisor, 0) - end - logger.apply_options(log_dir_perm: 0o777) - $log.out.close - - assert { path.parent.exist? } - assert_equal 0o777, (File.stat(path.parent).mode & 0xFFF) - end - - test 'rotate' do - path = @tmp_dir + 'log' + 'fluent.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5, log_rotate_size: 500) - logger.init(:supervisor, 0) - begin - 10.times.each do - $log.info "This is test message. This is test message. This is test message." - end - ensure - $log.out.close - end - - assert { path.parent.entries.size > 3 } # [".", "..", "logfile.log", ...] - end - - test 'rotate to max age' do - path = @tmp_dir + 'log' + 'fluent.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5, log_rotate_size: 500) - logger.init(:supervisor, 0) - begin - 100.times.each do - $log.info "This is test message. This is test message. This is test message." - end - ensure - $log.out.close - end - - assert { path.parent.entries.size == 7 } # [".", "..", "logfile.log", ...] - end - - test 'files for each process with rotate on Windows' do - omit "Only for Windows." unless Fluent.windows? - - path = @tmp_dir + 'log' + 'fluent.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5) - logger.init(:supervisor, 0) - $log.out.close - - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5) - logger.init(:worker0, 0) - $log.out.close - - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5) - logger.init(:workers, 1) - $log.out.close - - assert { path.parent.entries.size == 5 } # [".", "..", "logfile.log", ...] - end - - test 'reopen!' do - path = @tmp_dir + 'log' + 'fluent.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}) - logger.init(:supervisor, 0) - message = "This is test message." - $log.info message - logger.reopen! - $log.info message - $log.out.close - - assert { path.read.lines.select{ |line| line.include?(message) }.size == 2 } - end - - test 'reopen! with rotate reopens the same file' do - path = @tmp_dir + 'log' + 'fluent.log' - logger = Fluent::Supervisor::LoggerInitializer.new(path.to_s, Fluent::Log::LEVEL_DEBUG, nil, nil, {}, log_rotate_age: 5) - logger.init(:supervisor, 0) - logger.reopen! - $log.out.close - - assert { path.parent.entries.size == 3 } # [".", "..", "logfile.log", ...] - end -end diff --git a/test/test_supervisor.rb b/test/test_supervisor.rb index bc97c9c850..64915a7e4a 100644 --- a/test/test_supervisor.rb +++ b/test/test_supervisor.rb @@ -10,6 +10,7 @@ require 'fileutils' require 'tempfile' require 'securerandom' +require 'pathname' if Fluent.windows? require 'win32/event' @@ -680,6 +681,82 @@ def test_log_level_affects sv.configure assert_equal Fluent::Log::LEVEL_ERROR, $log.level end + + data(supervisor: true) + data(worker: false) + def test_log_path(supervisor) + log_path = Pathname(@tmp_dir) + "fluentd.log" + config_path = Pathname(@tmp_dir) + "fluentd.conf" + write_config config_path.to_s, "" + + s = Fluent::Supervisor.new(config_path: config_path.to_s, log_path: log_path.to_s) + assert_rr do + mock.proxy(File).chmod(0o777, log_path.parent.to_s).never + s.__send__(:setup_global_logger, supervisor: supervisor) + end + + assert { log_path.parent.exist? } + ensure + $log.out.close + end + + data(supervisor: true) + data(worker: false) + def test_dir_permission(supervisor) + omit "NTFS doesn't support UNIX like permissions" if Fluent.windows? + + log_path = Pathname(@tmp_dir) + "fluentd.log" + config_path = Pathname(@tmp_dir) + "fluentd.conf" + conf = <<~EOC + + dir_permission 0o777 + + EOC + write_config config_path.to_s, conf + + s = Fluent::Supervisor.new(config_path: config_path.to_s, log_path: log_path.to_s) + assert_rr do + mock.proxy(File).chmod(0o777, log_path.parent.to_s).once + s.__send__(:setup_global_logger, supervisor: supervisor) + end + + assert { log_path.parent.exist? } + assert { (File.stat(log_path.parent).mode & 0xFFF) == 0o777 } + ensure + $log.out.close + end + + def test_files_for_each_process_with_rotate_on_windows + omit "Only for Windows." unless Fluent.windows? + + log_path = Pathname(@tmp_dir) + "log" + "fluentd.log" + config_path = Pathname(@tmp_dir) + "fluentd.conf" + conf = <<~EOC + + + rotate_age 5 + + + EOC + write_config config_path.to_s, conf + + s = Fluent::Supervisor.new(config_path: config_path.to_s, log_path: log_path.to_s) + s.__send__(:setup_global_logger, supervisor: true) + $log.out.close + + s = Fluent::Supervisor.new(config_path: config_path.to_s, log_path: log_path.to_s) + s.__send__(:setup_global_logger, supervisor: false) + $log.out.close + + ENV["SERVERENGINE_WORKER_ID"] = "1" + s = Fluent::Supervisor.new(config_path: config_path.to_s, log_path: log_path.to_s) + s.__send__(:setup_global_logger, supervisor: false) + $log.out.close + + assert { log_path.parent.entries.size == 5 } # [".", "..", "logfile.log", ...] + ensure + ENV.delete("SERVERENGINE_WORKER_ID") + end end def test_enable_shared_socket From a9f511345a9adec2f4f5b78de8e741de3ef7de56 Mon Sep 17 00:00:00 2001 From: Daijiro Fukuda Date: Sun, 12 Mar 2023 20:17:44 +0900 Subject: [PATCH 9/9] LogTest: Make sure to close LogDeviceIO Signed-off-by: Daijiro Fukuda --- test/test_log.rb | 80 +++++++++++++++++++++++++----------------------- 1 file changed, 42 insertions(+), 38 deletions(-) diff --git a/test/test_log.rb b/test/test_log.rb index a344b532e3..29fd2a0ce9 100644 --- a/test/test_log.rb +++ b/test/test_log.rb @@ -602,44 +602,48 @@ def test_log_with_logdevio(expected) def test_log_rotates_specified_size_with_logdevio with_timezone('utc') do - rotate_age = 2 - rotate_size = 100 - path = "#{@tmp_dir}/log-dev-io-#{rotate_size}-#{rotate_age}" - path0 = path + '.0' - path1 = path + '.1' - - logdev = Fluent::LogDeviceIO.new(path, shift_age: rotate_age, shift_size: rotate_size) - logger = ServerEngine::DaemonLogger.new(logdev) - log = Fluent::Log.new(logger) - - msg = 'a' * 101 - log.info msg - assert_match msg, File.read(path) - assert_true File.exist?(path) - assert_true !File.exist?(path0) - assert_true !File.exist?(path1) - - # create log.0 - msg2 = 'b' * 101 - log.info msg2 - c = File.read(path) - c0 = File.read(path0) - assert_match msg2, c - assert_match msg, c0 - assert_true File.exist?(path) - assert_true File.exist?(path0) - assert_true !File.exist?(path1) - - # rotate - msg3 = 'c' * 101 - log.info msg3 - c = File.read(path) - c0 = File.read(path0) - assert_match msg3, c - assert_match msg2, c0 - assert_true File.exist?(path) - assert_true File.exist?(path0) - assert_true !File.exist?(path1) + begin + rotate_age = 2 + rotate_size = 100 + path = "#{@tmp_dir}/log-dev-io-#{rotate_size}-#{rotate_age}" + path0 = path + '.0' + path1 = path + '.1' + + logdev = Fluent::LogDeviceIO.new(path, shift_age: rotate_age, shift_size: rotate_size) + logger = ServerEngine::DaemonLogger.new(logdev) + log = Fluent::Log.new(logger) + + msg = 'a' * 101 + log.info msg + assert_match msg, File.read(path) + assert_true File.exist?(path) + assert_true !File.exist?(path0) + assert_true !File.exist?(path1) + + # create log.0 + msg2 = 'b' * 101 + log.info msg2 + c = File.read(path) + c0 = File.read(path0) + assert_match msg2, c + assert_match msg, c0 + assert_true File.exist?(path) + assert_true File.exist?(path0) + assert_true !File.exist?(path1) + + # rotate + msg3 = 'c' * 101 + log.info msg3 + c = File.read(path) + c0 = File.read(path0) + assert_match msg3, c + assert_match msg2, c0 + assert_true File.exist?(path) + assert_true File.exist?(path0) + assert_true !File.exist?(path1) + ensure + logdev&.close + end end end