From d21a12adf27e84858cff587a0d8c4a7373f63f59 Mon Sep 17 00:00:00 2001 From: Masahiro Nakagawa Date: Tue, 1 Sep 2020 10:04:44 +0900 Subject: [PATCH 1/2] log: Add ignore_same_log_interval Signed-off-by: Masahiro Nakagawa --- lib/fluent/log.rb | 36 +++++++++++++++++++++++++++++++++--- lib/fluent/supervisor.rb | 14 ++++++++++---- lib/fluent/system_config.rb | 3 ++- 3 files changed, 45 insertions(+), 8 deletions(-) diff --git a/lib/fluent/log.rb b/lib/fluent/log.rb index 23b65298b4..4c096a615e 100644 --- a/lib/fluent/log.rb +++ b/lib/fluent/log.rb @@ -113,6 +113,7 @@ def initialize(logger, opts={}) @suppress_repeated_stacktrace = opts[:suppress_repeated_stacktrace] @ignore_repeated_log_interval = opts[:ignore_repeated_log_interval] + @ignore_same_log_interval = opts[:ignore_same_log_interval] @process_type = opts[:process_type] # :supervisor, :worker0, :workers Or :standalone @process_type ||= :standalone # to keep behavior of existing code @@ -141,7 +142,8 @@ def dup dl_opts[:log_level] = @level - 1 logger = ServerEngine::DaemonLogger.new(@out, dl_opts) clone = self.class.new(logger, suppress_repeated_stacktrace: @suppress_repeated_stacktrace, process_type: @process_type, - worker_id: @worker_id, ignore_repeated_log_interval: @ignore_repeated_log_interval) + worker_id: @worker_id, ignore_repeated_log_interval: @ignore_repeated_log_interval, + ignore_same_log_interval: @ignore_same_log_interval) clone.format = @format clone.time_format = @time_format clone.log_event_enabled = @log_event_enabled @@ -151,7 +153,7 @@ def dup attr_reader :format attr_reader :time_format - attr_accessor :log_event_enabled, :ignore_repeated_log_interval + attr_accessor :log_event_enabled, :ignore_repeated_log_interval, :ignore_same_log_interval attr_accessor :out attr_accessor :level attr_accessor :optional_header, :optional_attrs @@ -428,6 +430,27 @@ def ignore_repeated_log?(key, time, message) (cached_log.msg == message) && (time - cached_log.time <= @ignore_repeated_log_interval) end + def ignore_same_log?(time, message) + cached_log = Thread.current[:last_same_log] + if cached_log.nil? + Thread.current[:last_same_log] = {message => time} + return false + end + + prev_time = cached_log[message] + if prev_time + if (time - prev_time) <= @ignore_same_log_interval + true + else + cached_log[message] = time + false + end + else + cached_log[message] = time + false + end + end + def suppress_stacktrace?(backtrace) cached_log = Thread.current[:last_repeated_stacktrace] return false if cached_log.nil? @@ -507,7 +530,11 @@ def event(level, args) end } - if @ignore_repeated_log_interval + if @ignore_same_log_interval + if ignore_same_log?(time, message) + return nil, nil + end + elsif @ignore_repeated_log_interval if ignore_repeated_log?(:last_repeated_log, time, message) return nil, nil else @@ -569,6 +596,9 @@ def initialize(logger) if logger.instance_variable_defined?(:@ignore_repeated_log_interval) @ignore_repeated_log_interval = logger.instance_variable_get(:@ignore_repeated_log_interval) end + if logger.instance_variable_defined?(:@ignore_same_log_interval) + @ignore_same_log_interval = logger.instance_variable_get(:@ignore_same_log_interval) + end self.format = @logger.format self.time_format = @logger.time_format diff --git a/lib/fluent/supervisor.rb b/lib/fluent/supervisor.rb index c1a59227be..464fe32ebd 100644 --- a/lib/fluent/supervisor.rb +++ b/lib/fluent/supervisor.rb @@ -302,6 +302,7 @@ def self.load_config(path, params = {}) log_level = params['log_level'] suppress_repeated_stacktrace = params['suppress_repeated_stacktrace'] ignore_repeated_log_interval = params['ignore_repeated_log_interval'] + ignore_same_log_interval = params['ignore_same_log_interval'] log_path = params['log_path'] chuser = params['chuser'] @@ -309,7 +310,8 @@ def self.load_config(path, params = {}) log_rotate_age = params['log_rotate_age'] log_rotate_size = params['log_rotate_size'] - log_opts = {suppress_repeated_stacktrace: suppress_repeated_stacktrace, ignore_repeated_log_interval: ignore_repeated_log_interval} + 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, @@ -347,6 +349,7 @@ def self.load_config(path, params = {}) chumask: 0, suppress_repeated_stacktrace: suppress_repeated_stacktrace, ignore_repeated_log_interval: ignore_repeated_log_interval, + ignore_same_log_interval: ignore_same_log_interval, daemonize: daemonize, rpc_endpoint: params['rpc_endpoint'], counter_server: params['counter_server'], @@ -441,10 +444,11 @@ def reopen! self end - def apply_options(format: nil, time_format: nil, log_dir_perm: nil, ignore_repeated_log_interval: nil) + def apply_options(format: nil, time_format: nil, log_dir_perm: nil, ignore_repeated_log_interval: nil, ignore_same_log_interval: 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 if @path && log_dir_perm File.chmod(log_dir_perm || 0755, File.dirname(@path)) @@ -511,7 +515,8 @@ def initialize(opt) @cl_opt = opt @conf = nil - log_opts = {suppress_repeated_stacktrace: opt[:suppress_repeated_stacktrace], ignore_repeated_log_interval: opt[:ignore_repeated_log_interval]} + 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, @@ -635,7 +640,8 @@ def configure(supervisor: false) 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_repeated_log_interval: @system_config.ignore_repeated_log_interval, + ignore_same_log_interval: @system_config.ignore_same_log_interval ) $log.info :supervisor, 'parsing config file is succeeded', path: @config_path diff --git a/lib/fluent/system_config.rb b/lib/fluent/system_config.rb index 15e7f1bbaf..b5e10714be 100644 --- a/lib/fluent/system_config.rb +++ b/lib/fluent/system_config.rb @@ -24,7 +24,7 @@ class SystemConfig SYSTEM_CONFIG_PARAMETERS = [ :workers, :root_dir, :log_level, :suppress_repeated_stacktrace, :emit_error_log_interval, :suppress_config_dump, - :log_event_verbose, :ignore_repeated_log_interval, + :log_event_verbose, :ignore_repeated_log_interval, :ignore_same_log_interval, :without_source, :rpc_endpoint, :enable_get_dump, :process_name, :file_permission, :dir_permission, :counter_server, :counter_client, :strict_config_value, :enable_msgpack_time_support @@ -35,6 +35,7 @@ class SystemConfig config_param :log_level, :enum, list: [:trace, :debug, :info, :warn, :error, :fatal], default: 'info' config_param :suppress_repeated_stacktrace, :bool, default: nil config_param :ignore_repeated_log_interval, :time, default: nil + config_param :ignore_same_log_interval, :time, default: nil config_param :emit_error_log_interval, :time, default: nil config_param :suppress_config_dump, :bool, default: nil config_param :log_event_verbose, :bool, default: nil From 4638886e9a50a736bd0632d70e095dd8f977f0fc Mon Sep 17 00:00:00 2001 From: Masahiro Nakagawa Date: Tue, 1 Sep 2020 10:52:45 +0900 Subject: [PATCH 2/2] log: Add test for ignore_same_log_interval Signed-off-by: Masahiro Nakagawa --- test/test_log.rb | 44 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 44 insertions(+) diff --git a/test/test_log.rb b/test/test_log.rb index e3d635b19e..bed0f2fb7c 100644 --- a/test/test_log.rb +++ b/test/test_log.rb @@ -411,6 +411,50 @@ def test_different_message end end + sub_test_case "ignore_same_log_interval" do + teardown do + Thread.current[:last_same_log] = nil + end + + def test_same_message + message = "This is test" + logger = ServerEngine::DaemonLogger.new(@log_device, {log_level: ServerEngine::DaemonLogger::INFO}) + log = Fluent::Log.new(logger, {ignore_same_log_interval: 5}) + + log.error message + 10.times { |i| + Timecop.freeze(@timestamp + i + 1) + log.error message + } + + expected = [ + "2016-04-21 02:58:41 +0000 [error]: This is test\n", + "2016-04-21 02:58:47 +0000 [error]: This is test\n" + ] + assert_equal(expected, log.out.logs) + end + + def test_different_message + message = "This is test" + logger = ServerEngine::DaemonLogger.new(@log_device, {log_level: ServerEngine::DaemonLogger::INFO}) + log = Fluent::Log.new(logger, {ignore_same_log_interval: 10}) + + log.error message + 3.times { |i| + Timecop.freeze(@timestamp + i) + log.error message + log.error message + log.info "Hello! " + message + } + + expected = [ + "2016-04-21 02:58:41 +0000 [error]: This is test\n", + "2016-04-21 02:58:41 +0000 [info]: Hello! This is test\n", + ] + assert_equal(expected, log.out.logs) + end + end + def test_dup dl_opts = {} dl_opts[:log_level] = ServerEngine::DaemonLogger::TRACE