Adds Audit Logging (json formatted) for user actions (#26)

* App registry client

* Add json-server mock for AppRegistry

* request_id logging; accept hash for log message

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

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

app/interactors/authenticate_identity.rb

@@ -1,6 +1,7 @@
 class AuthenticateIdentity
   include Interactor
   include FailOnError
+  include AuditLogging
 
   before do
     token = context.request.headers["Authorization"]

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|

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

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)

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

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

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 %>

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":"[email protected]","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":"[email protected]","cert_common_name":"example.com"), @log.readlines.last
+  end
+end

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