Refs #26561 - fixed log stack shutdown

config/settings.yml.example

@@ -45,8 +45,9 @@
 # Log level, one of UNKNOWN, FATAL, ERROR, WARN, INFO, DEBUG
 #:log_level: ERROR
 
-# The maximum size of a log file before it's rolled (in MiB)
-#:file_rolling_size: 100
+# The maximum size of a log file before it's rolled (in MiB) or zero to disable file rolling
+# and rely logrotate or similar tool
+#:file_rolling_size: 0
 
 # The maximum age of a log file before it's rolled (in seconds). Also accepts 'daily', 'weekly', or 'monthly'.
 #:file_rolling_age: weekly

lib/smart_proxy_dynflow_core/launcher.rb

@@ -17,6 +17,8 @@ def start(options)
       Rack::Server.new(rack_settings).start do |_server|
         SmartProxyDynflowCore::Core.ensure_initialized
       end
+      Log.instance.info "Finished shutting down"
+      Logging.shutdown
     end
 
     def load_settings!(options = {})

lib/smart_proxy_dynflow_core/log.rb

@@ -1,6 +1,25 @@
 require 'logging'
 
 module SmartProxyDynflowCore
+  class ReopenAppender < ::Logging::Appender
+    def initialize(name, logger, opts = {})
+      @reopen = false
+      @logger = logger
+      super(name, opts)
+    end
+
+    def set(status = true)
+      @reopen = status
+    end
+
+    def append(_event)
+      if @reopen
+        Logging.reopen
+        @reopen = false
+      end
+    end
+  end
+
   class Log
     BASE_LOG_SIZE = 1024 * 1024 # 1 MiB
     LOGGER_NAME = 'dynflow-core'.freeze
@@ -11,7 +30,6 @@ class Log
     rescue LoadError
       @syslog_available = false
     end
-    @reopen = false
 
     class << self
       def reload!
@@ -22,29 +40,20 @@ def reload!
       end
 
       def reopen
-        return if @logger.nil?
+        return if @logger.nil? || @reopen.nil?
         if Settings.instance.log_file !~ /^(STDOUT|SYSLOG|JOURNALD?)$/i
-          @logger.warn "Scheduled log file reopen"
-          @reopen = true
-        else
-          @logger.debug "Not scheduling log file reopen (no file appender)"
+          @reopen.set
         end
       end
 
-      def handle_reopen
-        @logger.warn "Performing log file reopen"
-        @reopen = false
-        @logger.appenders.each(&:reopen)
-        @logger.warn "Finished log file reopen"
-      end
-
       def instance
-        handle_reopen if @reopen
         return @logger if @logger
         layout = Logging::Layouts.pattern(pattern: Settings.instance.file_logging_pattern + "\n")
         notime_layout = Logging::Layouts.pattern(pattern: Settings.instance.system_logging_pattern + "\n")
         log_file = Settings.instance.log_file
         @logger = Logging.logger[LOGGER_NAME]
+        @reopen = ReopenAppender.new("Reopen dummy appender", @logger)
+        @logger.add_appenders(@reopen)
         if !Settings.instance.loaded || log_file.casecmp('STDOUT').zero?
           @logger.add_appenders(Logging.appenders.stdout(LOGGER_NAME, layout: layout))
         elsif log_file.casecmp('SYSLOG').zero?
@@ -65,7 +74,11 @@ def instance
             keep = Settings.instance.file_rolling_keep
             size = BASE_LOG_SIZE * Settings.instance.file_rolling_size
             age = Settings.instance.file_rolling_age
-            @logger.add_appenders(Logging.appenders.rolling_file(LOGGER_NAME, layout: layout, filename: log_file, keep: keep, size: size, age: age, roll_by: 'date'))
+            if size > 0
+              @logger.add_appenders(Logging.appenders.rolling_file(LOGGER_NAME, layout: layout, filename: log_file, keep: keep, size: size, age: age, roll_by: 'number'))
+            else
+              @logger.add_appenders(Logging.appenders.file(LOGGER_NAME, layout: layout, filename: log_file))
+            end
           rescue ArgumentError => ae
             @logger.add_appenders(Logging.appenders.stdout(LOGGER_NAME, layout: layout))
             @logger.warn "Log file #{log_file} cannot be opened. Falling back to STDOUT: #{ae}"

lib/smart_proxy_dynflow_core/middleware/keep_current_request_id.rb

@@ -42,7 +42,7 @@ def restore_current_request_id
         unless (restored_id = action.input[:current_request_id]).nil?
           old_id = ::Logging.mdc['request']
           if !old_id.nil? && old_id != restored_id
-            action.action_logger.warn(_('Changing request id %{request_id} to saved id %{saved_id}') % { :saved_id => restored_id, :request_id => old_id })
+            action.action_logger.warn('Changing request id %{request_id} to saved id %{saved_id}' % { :saved_id => restored_id, :request_id => old_id })
           end
           ::Logging.mdc['request'] = restored_id
         end

lib/smart_proxy_dynflow_core/settings.rb

@@ -45,7 +45,7 @@ class Settings < OpenStruct
       :file_logging_pattern => '%d %.8X{request} [%.1l] %m',
       :system_logging_pattern => '%.8X{request} [%.1l] %m',
       :file_rolling_keep => 6,
-      :file_rolling_size => 100,
+      :file_rolling_size => 0,
       :file_rolling_age => 'weekly'
     }.freeze
 

lib/smart_proxy_dynflow_core/test_action.rb

@@ -10,7 +10,12 @@
 module SmartProxyDynflowCore
   class TestAction < ::Dynflow::Action
     def run
-      raise "test exception" if input["exception"]
+      state = 0
+      while state < input[:debug_logs]
+        action_logger.debug("Test action counter at #{state}")
+        state += 1
+      end
+    raise "test exception" if input[:exception]
     end
   end
 end