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? 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/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, 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_log.rb b/test/test_log.rb index 480781d4d8..29fd2a0ce9 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 @@ -33,6 +34,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], @@ -593,45 +602,71 @@ 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' + 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 - logdev = Fluent::LogDeviceIO.new(path, shift_age: rotate_age, shift_size: rotate_size) - logger = ServerEngine::DaemonLogger.new(logdev) - log = Fluent::Log.new(logger) + def test_reopen + path = Pathname(@tmp_dir) + "fluent.log" - 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) + logdev = Fluent::LogDeviceIO.new(path.to_s) + logger = ServerEngine::DaemonLogger.new(logdev) + log = Fluent::Log.new(logger, path: path) - # 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) - end + 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 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 d2ffc2083d..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' @@ -29,6 +30,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 +38,7 @@ def setup end def teardown + $log = @stored_global_logger begin FileUtils.rm_rf(@tmp_dir) rescue Errno::EACCES @@ -322,6 +325,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"} @@ -564,141 +569,194 @@ 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 = %[ - - suppress_repeated_stacktrace false - ignore_repeated_log_interval 10s - ignore_same_log_interval 20s - - format json - time_format %FT%T.%L%z - - -] - write_config tmp_conf_path, conf_info_str - - 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 - - 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 + sub_test_case "init logger" do + 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 = <<~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 - assert_equal 5, logger.instance_variable_get(:@rotate_age) - assert_equal 1048576, logger.instance_variable_get(:@rotate_size) - end + s = Fluent::Supervisor.new({config_path: tmp_conf_path}) + s.configure(supervisor: supervisor) - data( - daily_age: 'daily', - weekly_age: 'weekly', - monthly_age: 'monthly', - 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) - - 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 + 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 - 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' } + 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, + ) + 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}) + 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 - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) - 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([3, 300], - [logger.instance_variable_get(:@rotate_age), - logger.instance_variable_get(:@rotate_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 - 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}) + 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]) } - log = sv.instance_variable_get(:@log) - log.init(:standalone, 0) - logger = $log.instance_variable_get(:@logger) + sv.configure + assert_equal Fluent::Log::LEVEL_ERROR, $log.level + end - assert_equal([3, 300], - [logger.instance_variable_get(:@rotate_age), - logger.instance_variable_get(:@rotate_size)]) + 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 - end - def test_inline_config - omit 'this feature is deprecated. see https://github.com/fluent/fluentd/issues/2711' + 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 - sv = Fluent::Supervisor.new({inline_config: '-'}) - assert_equal '-', sv.instance_variable_get(:@inline_config) + assert { log_path.parent.exist? } + assert { (File.stat(log_path.parent).mode & 0xFFF) == 0o777 } + ensure + $log.out.close + end - 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 + 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 - sv.configure - assert_equal inline_config, sv.instance_variable_get(:@inline_config) - end + 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 - def test_log_level_affects - sv = Fluent::Supervisor.new({}) + 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 - c = Fluent::Config::Element.new('system', '', { 'log_level' => 'error' }, []) - stub(Fluent::Config).build { config_element('ROOT', '', {}, [c]) } + 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 - sv.configure - assert_equal Fluent::Log::LEVEL_ERROR, $log.level + assert { log_path.parent.entries.size == 5 } # [".", "..", "logfile.log", ...] + ensure + ENV.delete("SERVERENGINE_WORKER_ID") + end end def test_enable_shared_socket @@ -732,14 +790,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