feat(logger): introduce audit logging

README.md

@@ -25,7 +25,36 @@ Or install it yourself as:
 
 ## Usage
 
-#### Insights::Api::Common::Filter
+### Insights::Api::Common::AuditLog
+
+Middleware and utility to add entries to an audit log.  By default it logs them to STDOUT,
+but eventually it can be tied into CloudWatch.
+Log entries are formatted into JSON, split by a new-line.
+
+Rails setup:
+```
+class Application < Rails::Application
+  ...
+  require 'insights/api/common'
+  config.middleware.use Insights::API::Common::AuditLog::Middleware
+end
+```
+
+Optionally the logger can be set up with:
+```
+Insights::API::Common::AuditLog.setup(Logger.new)
+```
+
+Setting context of an account (e.g. an authenticated account) can be done with these options
+```
+Insights::API::Common::AuditLog.with_account('12345')
+
+Insights::API::Common::AuditLog.with_account('12345') do
+  # limited context
+end
+```
+
+### Insights::Api::Common::Filter
 
 | Supported Comparators     | Comparator    |
 | ---------------------     | ----------    |

lib/insights/api/common.rb

@@ -1,3 +1,4 @@
+require "insights/api/common/audit_log"
 require "insights/api/common/custom_exceptions"
 require "insights/api/common/engine"
 require "insights/api/common/entitlement"

lib/insights/api/common/audit_log.rb

@@ -0,0 +1,41 @@
+# frozen_string_literal: true
+
+require_relative 'audit_log/formatter'
+require_relative 'audit_log/middleware'
+
+module Insights::API::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
+      end
+
+      def with_account(account_number)
+        original = Thread.current[:audit_account_number]
+        Thread.current[:audit_account_number] = account_number
+        return unless block_given?
+
+        yield
+        Thread.current[:audit_account_number] = original
+      end
+
+      private
+
+      def init_logger(logger = nil)
+        logger ||= Logger.new($stdout)
+        logger.level = Logger::INFO
+        logger.formatter = Formatter.new
+        logger
+      end
+    end
+  end
+end

lib/insights/api/common/audit_log/formatter.rb

@@ -0,0 +1,74 @@
+# frozen_string_literal: true
+
+require "manageiq/loggers"
+
+module Insights::API::Common
+  class AuditLog
+    class Formatter < ManageIQ::Loggers::Container::Formatter
+      ALLOWED_PAYLOAD_KEYS = %i[message account_number controller remote_ip
+                                transaction_id].freeze
+
+      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
+
+      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.kind_of?(Hash)
+          payload.merge!(msg.slice(*ALLOWED_PAYLOAD_KEYS))
+        else
+          payload[:message] = msg2str(msg)
+        end
+        payload
+      end
+
+      private
+
+      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 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
+      end
+
+      def rails_transation_id
+        ActiveSupport::Notifications.instrumenter.id
+      end
+    end
+  end
+end

lib/insights/api/common/audit_log/middleware.rb

@@ -0,0 +1,92 @@
+module Insights::API::Common
+  class AuditLog
+    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]
+        msg = "#{request.method} #{request.original_fullpath} -> #{status} #{status_label}"
+        if evidence[:unpermitted_parameters]
+          msg += "; unpermitted params #{fmt_params(evidence[:unpermitted_parameters])}"
+        end
+        if evidence[:halted_callback].present?
+          msg += "; filter chain halted by :#{evidence[:halted_callback]}"
+        end
+        msg
+      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
+
+      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
+
+      def unsubscribe
+        @subscribers.each do |sub|
+          ActiveSupport::Notifications.unsubscribe(sub)
+        end
+      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