Fixes #26561 - logging stack replaced

.gitignore

@@ -4,6 +4,7 @@
 /_yardoc/
 /coverage/
 /doc/
+/logs/*
 /pkg/
 /spec/reports/
 /tmp/

.rubocop.yml

@@ -23,14 +23,6 @@ Lint/ShadowingOuterLocalVariable:
 Lint/RescueException:
   Enabled: false
 
-Metrics/ClassLength:
-  Exclude:
-    - 'test/**/*'
-
-Metrics/BlockLength:
-  Exclude:
-    - 'test/**/*'
-
 Naming/AccessorMethodName:
   Enabled: false
 
@@ -46,8 +38,8 @@ Style/TrailingCommaInLiteral:
 Style/TrailingCommaInArguments:
   Enabled: false
 
-Metrics/LineLength:
-  Max: 120
+Style/FormatStringToken:
+  Enabled: false
 
 Style/StringLiterals:
   Enabled: false
@@ -70,9 +62,6 @@ Style/BracesAroundHashParameters:
 Style/SignalException:
   Enabled: false
 
-Metrics/MethodLength:
-  Max: 40
-
 Lint/AssignmentInCondition:
   Enabled: false
 
@@ -85,13 +74,7 @@ Lint/UnusedBlockArgument:
 Style/Next:
   Enabled: false
 
-Metrics/AbcSize:
-  Max: 30
-
-Metrics/CyclomaticComplexity:
-  Max: 15
-
-Metrics/ClassLength:
+Metrics:
   Enabled: false
 
 Style/RescueStandardError:

Gemfile

@@ -32,6 +32,7 @@ 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

@@ -39,11 +39,26 @@
 # Specify versions like: '1.1', or '1.2'
 #:tls_disabled_versions: []
 
-# File to log to, leave empty for logging to STDOUT
-# :log_file: /var/log/foreman-proxy/smart_proxy_dynflow_core.log
+# File to log to, leave empty for stdout or use STDOUT, STDERR, SYSLOG or JOURNAL
+#:log_file: /var/log/foreman-proxy/smart_proxy_dynflow_core.log
 
 # Log level, one of UNKNOWN, FATAL, ERROR, WARN, INFO, DEBUG
-# :log_level: ERROR
+#:log_level: ERROR
+
+# The maximum size of a log file before it's rolled (in MiB)
+#:file_rolling_size: 100
+
+# The maximum age of a log file before it's rolled (in seconds). Also accepts 'daily', 'weekly', or 'monthly'.
+#:file_rolling_age: weekly
+
+# Number of log files to keep
+#:file_rolling_keep: 6
+
+# Logging pattern for file-based loging
+#:file_logging_pattern: '%d %.8X{request} [%.1l] %m'
+
+# Logging pattern for syslog or journal loging
+#:system_logging_pattern: '%.8X{request} [%.1l] %m'
 
 # Maximum age of execution plans to keep before having them cleaned
 # by the execution plan cleaner (in seconds), defaults to 24 hours

lib/smart_proxy_dynflow/callback.rb

@@ -20,6 +20,7 @@ def relay(request, from, to)
                 end
           req['X-Forwarded-For'] = request.env['HTTP_HOST']
           req['AUTHORIZATION'] = request.env['HTTP_AUTHORIZATION']
+          req['X-Request-Id'] = env['HTTP_X_REQUEST_ID']
           response = send_request req
           Proxy::LogBuffer::Decorator.instance.debug "Proxy request status #{response.code} - #{response}"
           response

lib/smart_proxy_dynflow_core.rb

@@ -1,6 +1,8 @@
 raise LoadError, 'Ruby >= 2.1 is required' unless RUBY_VERSION >= '2.1'
 
 require 'dynflow'
+require 'smart_proxy_dynflow_core/request_id_middleware'
+require 'smart_proxy_dynflow_core/middleware/keep_current_request_id'
 require 'smart_proxy_dynflow_core/task_launcher_registry'
 require 'foreman_tasks_core'
 require 'smart_proxy_dynflow_core/log'

lib/smart_proxy_dynflow_core/api.rb

@@ -5,6 +5,10 @@ module SmartProxyDynflowCore
   class Api < ::Sinatra::Base
     helpers Helpers
 
+    configure do
+      ::Sinatra::Base.use ::SmartProxyDynflowCore::RequestIdMiddleware
+    end
+
     before do
       authorize_with_token || authorize_with_ssl_client
       content_type :json

lib/smart_proxy_dynflow_core/bundler_helper.rb

@@ -1,6 +1,5 @@
 module SmartProxyDynflowCore
   class BundlerHelper
-    # rubocop:disable Metrics/PerceivedComplexity
     def self.require_groups(*groups)
       if File.exist?(File.expand_path('../../../Gemfile.in', __FILE__))
         # If there is a Gemfile.in file, we will not use Bundler but BundlerExt

lib/smart_proxy_dynflow_core/callback.rb

@@ -15,7 +15,6 @@ def send_to_foreman_tasks(callback_info, data)
           self.new.callback(prepare_payload(callback_info, data))
         end
 
-        # rubocop:disable Metrics/PerceivedComplexity
         def ssl_options
           return @ssl_options if defined? @ssl_options
           @ssl_options = {}

lib/smart_proxy_dynflow_core/core.rb

@@ -15,7 +15,9 @@ def initialize
 
     def create_world(&block)
       config = default_world_config(&block)
-      ::Dynflow::World.new(config)
+      world = ::Dynflow::World.new(config)
+      world.middleware.use ::Actions::Middleware::KeepCurrentRequestID
+      world
     end
 
     def persistence_conn_string

lib/smart_proxy_dynflow_core/launcher.rb

@@ -47,7 +47,7 @@ def self.route_mapping(rack_builder)
 
     def install_usr1_trap
       trap(:USR1) do
-        Log.instance.roll_log
+        Log.reopen
       end
     end
 
@@ -83,7 +83,6 @@ def base_settings
       }
     end
 
-    # rubocop:disable Metrics/PerceivedComplexity
     def https_app
       ssl_options  = OpenSSL::SSL::SSLContext::DEFAULT_PARAMS[:options]
       ssl_options |= OpenSSL::SSL::OP_CIPHER_SERVER_PREFERENCE if defined?(OpenSSL::SSL::OP_CIPHER_SERVER_PREFERENCE)

lib/smart_proxy_dynflow_core/log.rb

@@ -1,61 +1,104 @@
-require 'logger'
+require 'logging'
 
 module SmartProxyDynflowCore
-  class Log < ::Logger
-    alias_method :write, :debug
+  class Log
+    BASE_LOG_SIZE = 1024 * 1024 # 1 MiB
+    begin
+      require 'syslog/logger'
+      @syslog_available = true
+    rescue LoadError
+      @syslog_available = false
+    end
 
     class << self
-      def instance
-        if @logger.nil?
-          @logger = self.new log_file
-          @logger.level = log_level
-        end
-        @logger
-      end
-
-      def instance=(logger)
-        @logger = logger
-      end
-
       def reload!
+        Logging.reset
         @logger = nil
         instance
       end
 
-      def log_level
-        if Settings.instance.loaded && Settings.instance.log_level
-          ::Logger.const_get(Settings.instance.log_level.upcase)
+      def reopen
+        return if @logger.nil?
+        @logger.appenders.each(&:reopen)
+      end
+
+      def instance
+        return @logger if @logger
+        logger_name = 'dynflow-core'
+        layout = Logging::Layouts.pattern(pattern: setting(:file_logging_pattern, '%d %.8X{request} [%.1l] %m') + "\n")
+        notime_layout = Logging::Layouts.pattern(pattern: setting(:system_logging_pattern, '%.8X{request} [%.1l] %m') + "\n")
+        log_file = setting(:log_file, 'STDOUT')
+        @logger = Logging.logger.root
+        if log_file.casecmp('STDOUT').zero?
+          @logger.add_appenders(Logging.appenders.stdout(logger_name, layout: layout))
+        elsif log_file.casecmp('SYSLOG').zero?
+          unless syslog_available?
+            puts "Syslog is not supported on this platform, use STDOUT or a file"
+            exit(1)
+          end
+          @logger.add_appenders(Logging.appenders.syslog(logger_name, layout: notime_layout, facility: ::Syslog::Constants::LOG_LOCAL5))
+        elsif log_file.casecmp('JOURNAL').zero? || log_file.casecmp('JOURNALD').zero?
+          begin
+            @logger.add_appenders(Logging.appenders.journald(logger_name, logger_name: :proxy_logger, layout: notime_layout, facility: ::Syslog::Constants::LOG_LOCAL5))
+          rescue NoMethodError
+            @logger.add_appenders(Logging.appenders.stdout(logger_name, layout: layout))
+            @logger.warn "Journald is not available on this platform. Falling back to STDOUT."
+          end
         else
-          Logger::WARN
+          begin
+            keep = setting(:file_rolling_keep, 6)
+            size = BASE_LOG_SIZE * setting(:file_rolling_size, 100)
+            age = setting(:file_rolling_age, 'weekly')
+            @logger.add_appenders(Logging.appenders.rolling_file(logger_name, layout: layout, filename: log_file, keep: keep, size: size, age: age, roll_by: 'date'))
+          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}"
+          end
         end
+        @logger.level = ::Logging.level_num(setting(:log_level, 'ERROR'))
+        @logger
       end
 
-      def log_file
-        if Settings.instance.loaded && Settings.instance.log_file
-          Settings.instance.log_file
+      def setting(name, default)
+        if Settings.instance.loaded && Settings.instance.send(name)
+          Settings.instance.send(name)
         else
-          $stdout
+          default
         end
       end
-    end
 
-    def initialize(file, *rest)
-      @file = file
-      @fd = @file.is_a?(IO) ? @file : File.open(@file, 'a')
-      @fd.sync = true
-      super(@fd, rest)
-    end
+      def with_fields(fields = {})
+        ::Logging.ndc.push(fields) do
+          yield
+        end
+      end
 
-    def roll_log
-      unless @file.is_a? IO
-        @fd.reopen @file, 'a'
-        @fd.sync = true
+      # Standard way for logging exceptions to get the most data in the log. By default
+      # it logs via warn level, this can be changed via options[:level]
+      def exception(context_message, exception, options = {})
+        level = options[:level] || :warn
+        unless ::Logging::LEVELS.keys.include?(level.to_s)
+          raise "Unexpected log level #{level}, expected one of #{::Logging::LEVELS.keys}"
+        end
+        # send class, message and stack as structured fields in addition to message string
+        backtrace = exception.backtrace ? exception.backtrace : []
+        extra_fields = {
+          exception_class: exception.class.name,
+          exception_message: exception.message,
+          exception_backtrace: backtrace
+        }
+        extra_fields[:foreman_code] = exception.code if exception.respond_to?(:code)
+        with_fields(extra_fields) do
+          public_send(level) do
+            ([context_message, "#{exception.class}: #{exception.message}"] + backtrace).join("\n")
+          end
+        end
       end
     end
 
     class ProxyStructuredFormater < ::Dynflow::LoggerAdapters::Formatters::Abstract
-      def call(_severity, _datetime, _prog_name, message)
-        if message.is_a?(::Exception)
+      def format(message)
+        if message.is_a?(Exception)
           subject = "#{message.message} (#{message.class})"
           if @base.respond_to?(:exception)
             @base.exception("Error details", message)
@@ -67,20 +110,32 @@ def call(_severity, _datetime, _prog_name, message)
           message
         end
       end
-
-      def format(message)
-        call(nil, nil, nil, message)
-      end
     end
 
     class ProxyAdapter < ::Dynflow::LoggerAdapters::Simple
       def initialize(logger, level = Logger::DEBUG, _formatters = [])
         @logger           = logger
         @logger.level     = level
-        @logger.formatter = ProxyStructuredFormater.new(@logger)
         @action_logger    = apply_formatters(ProgNameWrapper.new(@logger, ' action'), [ProxyStructuredFormater])
         @dynflow_logger   = apply_formatters(ProgNameWrapper.new(@logger, 'dynflow'), [ProxyStructuredFormater])
       end
     end
   end
 end
+
+class PryAction < ::Dynflow::Action
+  require 'pry'
+
+  def plan(args)
+    # logging
+    plan_self
+  end
+
+  def run
+    #binding.pry
+  end
+
+  def finalize
+    #binding.pry
+  end
+end

lib/smart_proxy_dynflow_core/webrick-patch.rb

@@ -7,7 +7,6 @@
 
 module WEBrick
   class GenericServer
-    # rubocop:disable Metrics/AbcSize
     def setup_ssl_context(config) # :nodoc:
       unless config[:SSLCertificate]
         cn = config[:SSLCertName]

smart_proxy_dynflow_core.gemspec

@@ -2,7 +2,6 @@ lib = File.expand_path('../lib', __FILE__)
 $LOAD_PATH.unshift(lib) unless $LOAD_PATH.include?(lib)
 require 'smart_proxy_dynflow_core/version'
 
-# rubocop:disable Metrics/BlockLength
 Gem::Specification.new do |gem|
   gem.name          = "smart_proxy_dynflow_core"
   gem.version       = SmartProxyDynflowCore::VERSION
@@ -31,10 +30,10 @@ Gem::Specification.new do |gem|
 
   gem.add_runtime_dependency('dynflow', "~> 1.1")
   gem.add_runtime_dependency('foreman-tasks-core', '>= 0.1.7')
+  gem.add_runtime_dependency('logging')
   gem.add_runtime_dependency('rack')
   gem.add_runtime_dependency('rest-client')
   gem.add_runtime_dependency('sequel')
   gem.add_runtime_dependency('sinatra')
   gem.add_runtime_dependency('sqlite3')
 end
-# rubocop:enable Metrics/BlockLength