log: add system_config option to force stacktrace level

Signed-off-by: Daijiro Fukuda <fukuda@clear-code.com>

Author: daipom

lib/fluent/log.rb

@@ -138,6 +138,7 @@ def initialize(logger, opts={})
       @optional_attrs = nil
 
       @suppress_repeated_stacktrace = opts[:suppress_repeated_stacktrace]
+      @forced_stacktrace_level = nil
       @ignore_repeated_log_interval = opts[:ignore_repeated_log_interval]
       @ignore_same_log_interval = opts[:ignore_same_log_interval]
 
@@ -240,6 +241,14 @@ def reopen!
       nil
     end
 
+    def force_stacktrace_level?
+      not @forced_stacktrace_level.nil?
+    end
+
+    def force_stacktrace_level(level)
+      @forced_stacktrace_level = level
+    end
+
     def enable_debug(b=true)
       @debug_mode = b
       self
@@ -500,6 +509,16 @@ def suppress_stacktrace?(backtrace)
     def dump_stacktrace(type, backtrace, level)
       return if @level > level
 
+      dump_stacktrace_internal(
+        type,
+        backtrace,
+        force_stacktrace_level? ? @forced_stacktrace_level : level,
+      )
+    end
+
+    def dump_stacktrace_internal(type, backtrace, level)
+      return if @level > level
+
       time = Time.now
 
       if @format == :text

lib/fluent/supervisor.rb

@@ -908,6 +908,7 @@ def setup_global_logger(supervisor: false)
         ignore_repeated_log_interval: system_config.ignore_repeated_log_interval,
         ignore_same_log_interval: system_config.ignore_same_log_interval,
       )
+      $log.force_stacktrace_level(system_config.log.forced_stacktrace_level) if system_config.force_stacktrace_level?
       $log.enable_color(false) if actual_log_path
       $log.enable_debug if system_config.log_level <= Fluent::Log::LEVEL_DEBUG
 

lib/fluent/system_config.rb

@@ -79,6 +79,7 @@ class SystemConfig
         end
       end
       config_param :rotate_size, :size, default: nil
+      config_param :forced_stacktrace_level, :enum, list: [:none, :trace, :debug, :info, :warn, :error, :fatal], default: :none
     end
 
     config_section :counter_server, multi: false do
@@ -118,6 +119,10 @@ class SystemConfig
       config_param :compress, :enum, list: [:text, :gzip], default: nil
     end
 
+    def force_stacktrace_level?
+      @log.forced_stacktrace_level != :none
+    end
+
     def self.create(conf, strict_config_value=false)
       systems = conf.elements(name: 'system')
       return SystemConfig.new if systems.empty?
@@ -162,6 +167,7 @@ def configure(conf, strict_config_value=false)
       end
 
       @log_level = Log.str_to_level(@log_level.to_s) if @log_level
+      @log[:forced_stacktrace_level] = Log.str_to_level(@log.forced_stacktrace_level.to_s) if force_stacktrace_level?
     end
 
     def dup

test/config/test_system_config.rb

@@ -82,6 +82,7 @@ def parse_text(text)
       assert_nil(sc.log.path)
       assert_equal(:text, sc.log.format)
       assert_equal('%Y-%m-%d %H:%M:%S %z', sc.log.time_format)
+      assert_equal(:none, sc.log.forced_stacktrace_level)
     end
 
     data(
@@ -124,6 +125,7 @@ def parse_text(text)
               path /tmp/fluentd.log
               format json
               time_format %Y
+              forced_stacktrace_level info
             </log>
           </system>
       EOS
@@ -133,6 +135,7 @@ def parse_text(text)
       assert_equal('/tmp/fluentd.log', sc.log.path)
       assert_equal(:json, sc.log.format)
       assert_equal('%Y', sc.log.time_format)
+      assert_equal(Fluent::Log::LEVEL_INFO, sc.log.forced_stacktrace_level)
     end
 
     # info is removed because info level can't be specified via command line

test/test_log.rb

@@ -386,6 +386,85 @@ def test_different_log_level
     end
   end
 
+  sub_test_case "force_stacktrace_level" do
+    data(
+      none: [ nil, ["trace", "debug", "info", "warn", "error", "fatal"] ],
+      trace: [ Fluent::Log::LEVEL_TRACE, ["trace", "trace", "trace", "trace", "trace", "trace"] ],
+      debug: [ Fluent::Log::LEVEL_DEBUG, ["debug", "debug", "debug", "debug", "debug", "debug"] ],
+      info: [ Fluent::Log::LEVEL_INFO, ["info", "info", "info", "info", "info", "info"] ],
+      warn: [ Fluent::Log::LEVEL_WARN, ["warn", "warn", "warn", "warn", "warn", "warn"] ],
+      error: [ Fluent::Log::LEVEL_ERROR, ["error", "error", "error", "error", "error", "error"] ],
+      fatal: [ Fluent::Log::LEVEL_FATAL, ["fatal", "fatal", "fatal", "fatal", "fatal", "fatal"] ],
+    )
+    test "level should be forced" do |(level, expected)|
+      backtrace = ["backtrace"]
+      logger = Fluent::Log.new(
+        ServerEngine::DaemonLogger.new(
+          @log_device,
+          log_level: ServerEngine::DaemonLogger::TRACE,
+        )
+      )
+      logger.force_stacktrace_level(level) unless level.nil?
+
+      logger.trace_backtrace(backtrace)
+      logger.debug_backtrace(backtrace)
+      logger.info_backtrace(backtrace)
+      logger.warn_backtrace(backtrace)
+      logger.error_backtrace(backtrace)
+      logger.fatal_backtrace(backtrace)
+
+      assert do
+        expected == logger.out.logs.map { |log| log.match(/ \[([a-z]+)\]: backtrace$/)[1] }
+      end
+    end
+
+    test "stacktraces that do not meet log_level initially should be discarded" do
+      logger = Fluent::Log.new(
+        ServerEngine::DaemonLogger.new(
+          @log_device,
+          log_level: ServerEngine::DaemonLogger::INFO,
+        )
+      )
+      logger.force_stacktrace_level(Fluent::Log::LEVEL_INFO)
+
+      logger.trace_backtrace(["trace"])
+      logger.debug_backtrace(["debug"])
+      logger.info_backtrace(["info"])
+      logger.warn_backtrace(["warn"])
+      logger.error_backtrace(["error"])
+      logger.fatal_backtrace(["fatal"])
+
+      assert_equal(
+        [
+          "  #{@timestamp_str} [info]: info\n",
+          "  #{@timestamp_str} [info]: warn\n",
+          "  #{@timestamp_str} [info]: error\n",
+          "  #{@timestamp_str} [info]: fatal\n",
+        ],
+        logger.out.logs,
+      )
+    end
+
+    test "stacktraces that do not meet log_level finally should be discarded" do
+      logger = Fluent::Log.new(
+        ServerEngine::DaemonLogger.new(
+          @log_device,
+          log_level: ServerEngine::DaemonLogger::INFO,
+        )
+      )
+      logger.force_stacktrace_level(Fluent::Log::LEVEL_DEBUG)
+
+      logger.trace_backtrace(["trace"])
+      logger.debug_backtrace(["debug"])
+      logger.info_backtrace(["info"])
+      logger.warn_backtrace(["warn"])
+      logger.error_backtrace(["error"])
+      logger.fatal_backtrace(["fatal"])
+
+      assert_equal([], logger.out.logs)
+    end
+  end
+
   sub_test_case "ignore_repeated_log_interval" do
     def test_same_message
       message = "This is test"

test/test_supervisor.rb

@@ -715,6 +715,7 @@ def test_init_for_logger(supervisor)
           <log>
             format json
             time_format %FT%T.%L%z
+            forced_stacktrace_level info
           </log>
         </system>
       EOC
@@ -728,6 +729,8 @@ def test_init_for_logger(supervisor)
       assert_equal false, $log.suppress_repeated_stacktrace
       assert_equal 10, $log.ignore_repeated_log_interval
       assert_equal 20, $log.ignore_same_log_interval
+      assert_equal Fluent::Log::LEVEL_INFO, $log.instance_variable_get(:@forced_stacktrace_level)
+      assert_true $log.force_stacktrace_level?
     end
 
     data(