feat(logging): RHICOMPL-1217 introduce audit logging

Gemfile

@@ -60,6 +60,9 @@ gem 'uuid'
 # Prometheus exporter
 gem 'prometheus_exporter', '>= 0.5'
 
+# Logging, incl. CloudWatch
+gem 'manageiq-loggers', '~> 0.6.0'
+
 # Parsing OpenSCAP reports library
 gem 'openscap_parser', '~> 1.0.0'
 

Gemfile.lock

@@ -157,6 +157,10 @@ GEM
       systemu (~> 2.6.5)
     mail (2.7.1)
       mini_mime (>= 0.1.1)
+    manageiq-loggers (0.6.0)
+      activesupport (>= 5.0)
+      manageiq-password (~> 0.1)
+    manageiq-password (0.3.0)
     marcel (0.3.3)
       mimemagic (~> 0.3.2)
     method_source (1.0.0)
@@ -357,6 +361,7 @@ DEPENDENCIES
   graphql-batch
   irb (>= 1.2)
   listen (>= 3.0.5, < 3.2)
+  manageiq-loggers (~> 0.6.0)
   minitest-reporters
   mocha
   oj

lib/audit_log/audit_log.rb

@@ -0,0 +1,50 @@
+# frozen_string_literal: true
+
+require_relative 'audit_log/formatter'
+require_relative 'audit_log/middleware'
+
+# Common space for Insights API stuff
+module Insights
+  module API
+    module Common
+      # Audit Logger into selected logger, but primarily to CloudWatch
+      class AuditLog
+        class << self
+          def logger
+            @logger ||= init_logger
+          end
+
+          def logger=(logger)
+            @logger = init_logger(logger)
+          end
+
+          def setup(logger = nil)
+            self.logger = logger
+            self
+          end
+
+          def with_account(account_number)
+            original = Thread.current[:audit_account_number]
+            Thread.current[:audit_account_number] = account_number
+            return unless block_given?
+
+            begin
+              yield
+            ensure
+              Thread.current[:audit_account_number] = original
+            end
+          end
+
+          private
+
+          def init_logger(logger = nil)
+            logger ||= Logger.new($stdout)
+            logger.level = Logger::INFO
+            logger.formatter = Formatter.new
+            logger
+          end
+        end
+      end
+    end
+  end
+end

lib/audit_log/audit_log/formatter.rb

@@ -0,0 +1,80 @@
+# frozen_string_literal: true
+
+require 'manageiq/loggers'
+
+# Common space for Insights API stuff
+module Insights
+  module API
+    module Common
+      class AuditLog
+        # Audit Log formatter with evidence capture
+        class Formatter < ManageIQ::Loggers::Container::Formatter
+          ALLOWED_PAYLOAD_KEYS = %i[message account_number controller remote_ip
+                                    transaction_id].freeze
+
+          # rubocop:disable Metrics/MethodLength
+          def call(severity, time, progname, msg)
+            payload = {
+              '@timestamp': format_datetime(time),
+              hostname: hostname,
+              pid: $PROCESS_ID,
+              thread_id: thread_id,
+              service: progname,
+              level: translate_error(severity),
+              account_number: account_number
+            }
+            payload.merge!(framework_evidence)
+            JSON.generate(merge_message(payload, msg).compact) << "\n"
+          end
+          # rubocop:enable Metrics/MethodLength
+
+          def framework_evidence
+            sidekiq_ctx = sidekiq_current_ctx
+            if sidekiq_ctx
+              { controller: sidekiq_ctx[:class],
+                transaction_id: sidekiq_ctx[:jid] }
+            else
+              { transaction_id: rails_transation_id }
+            end
+          end
+
+          def merge_message(payload, msg)
+            if msg.is_a?(Hash)
+              payload.merge!(msg.slice(*ALLOWED_PAYLOAD_KEYS))
+            else
+              payload[:message] = msg2str(msg)
+            end
+            payload
+          end
+
+          private
+
+          def sidekiq_current_ctx
+            return unless Module.const_defined?(:Sidekiq)
+
+            if ::Sidekiq.const_defined?(:Context)
+              Sidekiq::Context.current
+            else
+              # versions up to 6.0.0
+              Thread.current[:sidekiq_context]
+            end
+          rescue NoMethodError
+            nil
+          end
+
+          def format_datetime(time)
+            time.utc.strftime('%Y-%m-%dT%H:%M:%S.%6NZ')
+          end
+
+          def account_number
+            Thread.current[:audit_account_number]
+          end
+
+          def rails_transation_id
+            ActiveSupport::Notifications.instrumenter.id
+          end
+        end
+      end
+    end
+  end
+end

lib/audit_log/audit_log/middleware.rb

@@ -0,0 +1,116 @@
+# frozen_string_literal: true
+
+# Common space for Insights API stuff
+module Insights
+  module API
+    module Common
+      class AuditLog
+        # Request events listener, capturing for evidence
+        class Middleware
+          attr_reader :logger, :evidence, :request, :status
+
+          def initialize(app)
+            @app = app
+            @logger = AuditLog.logger
+            @subscribers = []
+            @evidence = {}
+          end
+
+          def call(env)
+            subscribe
+            @request = ActionDispatch::Request.new(env)
+            @app.call(env).tap do |status, _headers, _body|
+              @status = status
+              response_finished
+            end
+          ensure
+            unsubscribe
+          end
+
+          private
+
+          def response_finished
+            payload = {
+              controller: evidence[:controller],
+              remote_ip: request.remote_ip,
+              message: generate_message
+            }
+            log(payload)
+          end
+
+          def generate_message
+            status_label = Rack::Utils::HTTP_STATUS_CODES[status]
+            parts = [
+              "#{request.method} #{request.original_fullpath}" \
+              " -> #{status} #{status_label}",
+              unpermitted_params_msg,
+              halted_cb_msg
+            ]
+            parts.compact.join('; ')
+          end
+
+          def unpermitted_params_msg
+            params = evidence[:unpermitted_parameters]
+            return if params.blank?
+
+            "unpermitted params #{fmt_params(params)}"
+          end
+
+          def halted_cb_msg
+            return if evidence[:halted_callback].blank?
+
+            "filter chain halted by :#{evidence[:halted_callback]}"
+          end
+
+          def log(payload)
+            if status < 400
+              logger.info(payload)
+            elsif status < 500
+              logger.warn(payload)
+            else
+              logger.error(payload)
+            end
+          end
+
+          def subscribe
+            @subscribers << subscribe_conroller
+          end
+
+          # rubocop:disable Metrics/MethodLength
+          def subscribe_conroller
+            ActiveSupport::Notifications.subscribe(/\.action_controller$/) do
+              |name, _started, _finished, _unique_id, payload|
+              # https://guides.rubyonrails.org/active_support_instrumentation.html#action-controller
+              case name.split('.')[0]
+              when 'process_action'
+                @evidence[:controller] = fmt_controller(payload)
+              when 'halted_callback'
+                @evidence[:halted_callback] = payload[:filter]
+              when 'unpermitted_parameters'
+                @evidence[:unpermitted_parameters] = payload[:keys]
+              end
+            end
+          end
+          # rubocop:enable Metrics/MethodLength
+
+          def unsubscribe
+            @subscribers.each do |sub|
+              ActiveSupport::Notifications.unsubscribe(sub)
+            end
+            @subscribers.clear
+          end
+
+          def fmt_controller(payload)
+            return if payload[:controller].blank?
+
+            [payload[:controller], payload[:action]].compact.join('#')
+          end
+
+          def fmt_params(params)
+            params.map { |e| ":#{e}" }.join(', ')
+          end
+        end
+      end
+    end
+  end
+end

test/lib/audit_log/audit_log_test.rb

@@ -0,0 +1,62 @@
+# frozen_string_literal: true
+
+require 'test_helper'
+require 'audit_log/audit_log'
+
+class AuditLogTest < ActiveSupport::TestCase
+  setup do
+    @output = StringIO.new
+    @logger = Logger.new(@output)
+    @audit = Insights::API::Common::AuditLog.setup(@logger)
+  end
+
+  def capture_log(msg)
+    @audit.logger.info(msg)
+    @output.rewind # logger seems to read what it's writing?
+    JSON.parse @output.readlines[-1]
+  end
+
+  test 'logs a general message formatted into JSON' do
+    log_msg = capture_log('Audit message')
+    assert_equal 'Audit message', log_msg['message']
+  end
+
+  test 'logs include general evidence' do
+    @audit.logger.info('Audit message')
+    line = @output.string
+    assert line
+
+    log_msg = JSON.parse(line).compact
+    assert_equal log_msg.keys.sort, %w[
+      @timestamp
+      hostname
+      pid
+      thread_id
+      level
+      transaction_id
+      message
+    ].sort
+  end
+
+  test 'setting account number' do
+    begin
+      @audit.with_account('1')
+      log_msg = capture_log('Audit message')
+      assert_equal '1', log_msg['account_number']
+
+      @audit.with_account('2') do
+        log_msg = capture_log('Audit message')
+        assert_equal '2', log_msg['account_number']
+      end
+
+      log_msg = capture_log('Audit message')
+      assert_equal '1', log_msg['account_number']
+
+      @audit.with_account(nil)
+      log_msg = capture_log('Audit message')
+      assert_not log_msg['account_number']
+    ensure
+      @audit.with_account(nil)
+    end
+  end
+end