Refs #26561 - fixed log stack shutdown

Gemfile

@@ -32,7 +32,6 @@ else
   gem 'rack', '>= 1.1'
   gem 'sinatra'
 end
-gem 'logging-journald', '~> 2.0', :platforms => [:ruby]
 
 # load bundler.d
 Dir["#{File.dirname(__FILE__)}/bundler.d/*.rb"].each do |bundle|

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 on 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/api.rb

@@ -7,9 +7,11 @@ class Api < ::Sinatra::Base
     helpers Helpers
 
     configure do
-      ::Sinatra::Base.set :logging, false
-      ::Sinatra::Base.use ::SmartProxyDynflowCore::RequestIdMiddleware
-      ::Sinatra::Base.use ::SmartProxyDynflowCore::LoggerMiddleware
+      if Settings.instance.standalone
+        ::Sinatra::Base.set :logging, false
+        ::Sinatra::Base.use ::SmartProxyDynflowCore::RequestIdMiddleware
+        ::Sinatra::Base.use ::SmartProxyDynflowCore::LoggerMiddleware
+      end
     end
 
     before do

lib/smart_proxy_dynflow_core/launcher.rb

@@ -16,13 +16,15 @@ def self.launch!(options)
     end
 
     def start(options)
-      load_settings!(options)
       Settings.instance.standalone = true
+      load_settings!(options)
       install_usr1_trap
       Rack::Server.new(rack_settings).start do |_server|
         SmartProxyDynflowCore::Core.ensure_initialized
         ::SdNotify.ready
       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,21 @@ 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 ::Proxy::LogBuffer::Decorator.instance unless Settings.instance.standalone
         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
+        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 +75,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/logger_middleware.rb

@@ -13,7 +13,7 @@ def call(env)
       @logger.debug { 'Headers: ' + env.select { |k, v| k.start_with? 'HTTP_' }.inspect }
       if @logger.debug? && env['rack.input']
         body = env['rack.input'].read
-        @logger.debug body.empty? ? '' : 'Body: ' + body
+        @logger.debug('Body: ' + body) unless body.empty?
         env['rack.input'].rewind
       end
       status, = @app.call(env)

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
 

smart_proxy_dynflow.gemspec

@@ -19,10 +19,12 @@ Gem::Specification.new do |gem|
   gem.require_paths = ["lib"]
   gem.license = 'GPL-3.0'
 
+  gem.add_runtime_dependency "logging"
+
   gem.add_development_dependency "bundler", ">= 1.7"
-  gem.add_development_dependency('minitest')
-  gem.add_development_dependency('mocha', '~> 1')
-  gem.add_development_dependency('rack-test', '~> 0')
+  gem.add_development_dependency 'minitest'
+  gem.add_development_dependency 'mocha', '~> 1'
+  gem.add_development_dependency 'rack-test', '~> 0'
   gem.add_development_dependency "rake", "~> 10.0"
-  gem.add_development_dependency('webmock', '~> 1')
+  gem.add_development_dependency 'webmock', '~> 1'
 end