From 04d8aa0944bfb01a1322708f83c45deed410af2d Mon Sep 17 00:00:00 2001 From: Viliam Krizan Date: Tue, 2 Feb 2021 17:30:44 +0100 Subject: [PATCH 1/2] feat(logger): introduce audit logging --- README.md | 31 ++++++- lib/insights/api/common.rb | 1 + lib/insights/api/common/audit_log.rb | 41 +++++++++ .../api/common/audit_log/formatter.rb | 51 ++++++++++ .../api/common/audit_log/middleware.rb | 92 +++++++++++++++++++ 5 files changed, 215 insertions(+), 1 deletion(-) create mode 100644 lib/insights/api/common/audit_log.rb create mode 100644 lib/insights/api/common/audit_log/formatter.rb create mode 100644 lib/insights/api/common/audit_log/middleware.rb diff --git a/README.md b/README.md index 9764eab7..4e06e411 100644 --- a/README.md +++ b/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 | | --------------------- | ---------- | diff --git a/lib/insights/api/common.rb b/lib/insights/api/common.rb index cf5d91a3..d980a54c 100644 --- a/lib/insights/api/common.rb +++ b/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" diff --git a/lib/insights/api/common/audit_log.rb b/lib/insights/api/common/audit_log.rb new file mode 100644 index 00000000..2935e28d --- /dev/null +++ b/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 diff --git a/lib/insights/api/common/audit_log/formatter.rb b/lib/insights/api/common/audit_log/formatter.rb new file mode 100644 index 00000000..e77f8654 --- /dev/null +++ b/lib/insights/api/common/audit_log/formatter.rb @@ -0,0 +1,51 @@ +# 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 + } + JSON.generate(merge_message(payload, msg).compact) << "\n" + 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[:transaction_id] = transaction_id if payload[:transaction_id].blank? + 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 transaction_id + ActiveSupport::Notifications.instrumenter.id + # TODO: Sidekiq job id + # TODO: Racecar id + end + end + end +end diff --git a/lib/insights/api/common/audit_log/middleware.rb b/lib/insights/api/common/audit_log/middleware.rb new file mode 100644 index 00000000..e3f295b8 --- /dev/null +++ b/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 From 58e6586d412ec9d39c3a0032eda6d2b5b0f02356 Mon Sep 17 00:00:00 2001 From: Viliam Krizan Date: Wed, 3 Feb 2021 12:19:00 +0100 Subject: [PATCH 2/2] feat(logger): sidekiq evidence for audit log --- .../api/common/audit_log/formatter.rb | 31 ++++++++++++++++--- 1 file changed, 27 insertions(+), 4 deletions(-) diff --git a/lib/insights/api/common/audit_log/formatter.rb b/lib/insights/api/common/audit_log/formatter.rb index e77f8654..3c7700bb 100644 --- a/lib/insights/api/common/audit_log/formatter.rb +++ b/lib/insights/api/common/audit_log/formatter.rb @@ -18,16 +18,30 @@ def call(severity, time, progname, msg) :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[:transaction_id] = transaction_id if payload[:transaction_id].blank? payload end @@ -41,10 +55,19 @@ def account_number Thread.current[:audit_account_number] end - def transaction_id + 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 - # TODO: Sidekiq job id - # TODO: Racecar id end end end