diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb index 02bc7ff..1fb0a84 100644 --- a/app/controllers/application_controller.rb +++ b/app/controllers/application_controller.rb @@ -1,5 +1,6 @@ class ApplicationController < ActionController::API before_action :set_default_format + before_action :store_request_id rescue_from StandardError, with: :handle_standard_error rescue_from AuthError, with: :handle_auth_error rescue_from BadRequestError, with: :handle_bad_request_error @@ -22,6 +23,10 @@ def set_default_format request.format = :json end + def store_request_id + Thread.current[:request_id] = request.uuid + end + def handle_standard_error(exception) render json: { error: exception.message }, status: :internal_server_error end diff --git a/app/interactors/audit_logging.rb b/app/interactors/audit_logging.rb new file mode 100644 index 0000000..ee5660b --- /dev/null +++ b/app/interactors/audit_logging.rb @@ -0,0 +1,28 @@ +module AuditLogging + extend ActiveSupport::Concern + + included do + around do |interactor| + interactor.call + log + rescue => e + log + raise e + end + end + + private + + def log + result = context.success? ? "success" : "failure" + level = context.success? ? :info : :error + payload = { + action: "#{self.class.name}", + result: result, + error: context.error&.message, + subject: context.identity&.subject, + cert_common_name: context.request&.try(:common_name) + } + AuditLogger.new.send(level, payload) + end +end diff --git a/app/interactors/authenticate_identity.rb b/app/interactors/authenticate_identity.rb index b7462e8..c274d64 100644 --- a/app/interactors/authenticate_identity.rb +++ b/app/interactors/authenticate_identity.rb @@ -1,6 +1,7 @@ class AuthenticateIdentity include Interactor include FailOnError + include AuditLogging before do token = context.request.headers["Authorization"] diff --git a/app/interactors/authorize_request.rb b/app/interactors/authorize_request.rb index d768383..85ae6bb 100644 --- a/app/interactors/authorize_request.rb +++ b/app/interactors/authorize_request.rb @@ -1,6 +1,8 @@ class AuthorizeRequest include Interactor include FailOnError + include AuditLogging + def call context.request.fqdns.each do |fqdn| diff --git a/app/interactors/issue_cert.rb b/app/interactors/issue_cert.rb index 667043f..d2513f8 100644 --- a/app/interactors/issue_cert.rb +++ b/app/interactors/issue_cert.rb @@ -2,5 +2,5 @@ class IssueCert include Interactor::Organizer include FailOnError - organize RefreshDomain, AuthorizeRequest, ObtainCert, Log + organize RefreshDomain, AuthorizeRequest, ObtainCert end diff --git a/app/interactors/obtain_cert.rb b/app/interactors/obtain_cert.rb index 54c893a..bb07a2d 100644 --- a/app/interactors/obtain_cert.rb +++ b/app/interactors/obtain_cert.rb @@ -1,6 +1,7 @@ class ObtainCert include Interactor include FailOnError + include AuditLogging def call if cert = Services::CertificateService.issue_cert(context.request) diff --git a/app/lib/audit_log_formatter.rb b/app/lib/audit_log_formatter.rb new file mode 100644 index 0000000..0304ea4 --- /dev/null +++ b/app/lib/audit_log_formatter.rb @@ -0,0 +1,17 @@ +class AuditLogFormatter < ActiveSupport::Logger::SimpleFormatter + def call(severity, timestamp, _progname, message) + # request_id is unique to the life of the api request + request_id = Thread.current[:request_id] + json = { + type: severity, + time: "#{timestamp}", + request_id: request_id + } + if message.is_a? Hash + json = json.merge(message) + else + json[:message] = message + end + "#{json.to_json}\n" + end +end diff --git a/app/lib/audit_logger.rb b/app/lib/audit_logger.rb new file mode 100644 index 0000000..b048687 --- /dev/null +++ b/app/lib/audit_logger.rb @@ -0,0 +1,6 @@ +class AuditLogger < ActiveSupport::Logger + def initialize + super(Rails.configuration.astral[:audit_log_file]) + self.formatter = AuditLogFormatter.new + end +end diff --git a/config/astral.yml b/config/astral.yml index f4d61c6..76592b4 100644 --- a/config/astral.yml +++ b/config/astral.yml @@ -9,6 +9,7 @@ shared: app_registry_ca_file: <%= ENV["APP_REGISTRY_CA_FILE"] %> app_registry_client_cert: <%= ENV["APP_REGISTRY_CLIENT_CERT"] %> app_registry_client_key: <%= ENV["APP_REGISTRY_CLIENT_KEY"] %> + audit_log_file: <%= ENV["AUDIT_LOG_FILE"] || "#{Rails.root.join('log')}/astral-audit.log" %> test: cert_ttl: <%= 24.hours.in_seconds %> diff --git a/test/interactors/audit_logging_test.rb b/test/interactors/audit_logging_test.rb new file mode 100644 index 0000000..ad864a9 --- /dev/null +++ b/test/interactors/audit_logging_test.rb @@ -0,0 +1,43 @@ +require "test_helper" + +class AuditLoggingTest < ActiveSupport::TestCase + def setup + @domain = domains(:owner_match) + @identity = Identity.new(subject: @domain.users_array.first) + @cr = CertIssueRequest.new(common_name: @domain.fqdn) + @log = Tempfile.new("log-test") + Rails.configuration.astral[:audit_log_file] = @log.path + end + + def teardown + @log.close + @log.unlink + end + + test ".call will be logged as success" do + Object.const_set("SuccessAction", Class.new do + include Interactor + include AuditLogging + + def call + end + end) + rslt = SuccessAction.call(identity: @identity, request: @cr) + assert rslt.success? + assert_match %Q("action":"SuccessAction","result":"success","error":null,"subject":"john.doe@example.com","cert_common_name":"example.com"), @log.readlines.last + end + + test ".call will be logged as failure" do + Object.const_set("FailAction", Class.new do + include Interactor + include AuditLogging + + def call + context.fail! + end + end) + rslt = FailAction.call(identity: @identity, request: @cr) + assert_not rslt.success? + assert_match %Q("action":"FailAction","result":"failure","error":null,"subject":"john.doe@example.com","cert_common_name":"example.com"), @log.readlines.last + end +end diff --git a/test/lib/audit_log_formatter_test.rb b/test/lib/audit_log_formatter_test.rb new file mode 100644 index 0000000..e23e185 --- /dev/null +++ b/test/lib/audit_log_formatter_test.rb @@ -0,0 +1,28 @@ +require "test_helper" + +class AuditLogFormatterTest < ActiveSupport::TestCase + setup do + Thread.current[:request_id] = nil + end + + test "#call formats logformatter inputs as json" do + t = Time.now + result = AuditLogFormatter.new.call("info", t, nil, "some message") + assert_equal %Q({"type":"info","time":"#{t}","request_id":null,"message":"some message"}\n), result + end + + test "#call accepts and merges a Hash type for the message" do + t = Time.now + result = AuditLogFormatter.new.call("info", t, nil, { key: "some message", key2: "another" }) + assert_equal %Q({"type":"info","time":"#{t}","request_id":null,"key":"some message","key2":"another"}\n), result + end + + test "#call can render a thread local request_id" do + t = Time.now + req_id = SecureRandom.hex + Thread.stub :current, { request_id: req_id } do + result = AuditLogFormatter.new.call("info", t, nil, { key: "some message" }) + assert_equal %Q({"type":"info","time":"#{t}","request_id":"#{req_id}","key":"some message"}\n), result + end + end +end