MAP-582: Log correct response codes in access logs

app/controllers/api_controller.rb

@@ -20,6 +20,7 @@ class ApiController < ApplicationController
   CONTENT_TYPE = 'application/vnd.api+json'
   REGEXP_API_VERSION = %r{.*version=(?<version>\d+)}
 
+  # NOTE: these may need to be added to EXTRA_RESCUE_RESPONSES below to show up correctly in the access logs
   rescue_from ActionController::ParameterMissing, with: :render_bad_request_error
   rescue_from ActiveRecord::RecordNotFound, with: :render_resource_not_found_error
   rescue_from ActiveRecord::RecordInvalid, with: :render_unprocessable_entity_error
@@ -34,6 +35,18 @@ class ApiController < ApplicationController
   rescue_from Faraday::TimeoutError, with: :render_timeout_error
   rescue_from OAuth2::Error, with: :render_nomis_bad_gateway
 
+  # Response codes for the access logs which aren't automatically converted by Rails
+  EXTRA_RESCUE_RESPONSES = {
+    'ActiveRecord::ReadOnlyRecord' => :forbidden,
+    'CanCan::AccessDenied' => :unauthorized,
+    'ActiveModel::ValidationError' => :unprocessable_entity,
+    'IncludeParamsValidator::ValidationError' => :bad_request,
+    'NotSupportedInOldVersionError' => :not_acceptable,
+    'Faraday::ConnectionFailed' => :service_unavailable,
+    'Faraday::TimeoutError' => :gateway_timeout,
+    'OAuth2::Error' => :bad_gateway,
+  }.freeze
+
   def current_user
     return Doorkeeper::Application.new unless authentication_enabled?
 
@@ -339,6 +352,10 @@ def log_controller_entry
 
   def write_access_log
     yield
+    status_code = response.code
+  rescue StandardError => e
+    rescue_responses = ActionDispatch::ExceptionWrapper.rescue_responses.merge(EXTRA_RESCUE_RESPONSES)
+    status_code = Rack::Utils.status_code(rescue_responses[e.class.to_s])
   ensure
     create_doc = controller_name == 'documents' && request.params['action'] == 'create'
     body = request.raw_post unless create_doc
@@ -351,7 +368,7 @@ def write_access_log
       controller_name:,
       path: request.path,
       params: request.query_parameters,
-      code: response.code,
+      code: status_code,
       idempotency_key: request.headers['Idempotency-Key'],
       body:,
     )

spec/requests/api/access_logs_spec.rb

@@ -0,0 +1,90 @@
+require 'rails_helper'
+
+RSpec.describe 'Access logs' do
+  let(:access_token) { 'spoofed-token' }
+  let(:content_type) { ApiController::CONTENT_TYPE }
+
+  let(:headers) do
+    {
+      'Content-Type' => content_type,
+      'Authorization' => "Bearer #{access_token}",
+      'Idempotency-Key' => SecureRandom.uuid,
+    }
+  end
+
+  let(:access_log) { AccessLog.order(:timestamp).last }
+
+  context 'when listing moves' do
+    before { get '/api/moves', headers: }
+
+    it 'logs the correct response code' do
+      expect(access_log.code).to eq('200')
+    end
+  end
+
+  context 'when creating a move' do
+    let(:move_attributes) do
+      { date: Time.zone.today,
+        time_due: Time.zone.now,
+        status: 'requested',
+        additional_information: 'some more info',
+        move_type: 'court_appearance' }
+    end
+
+    let(:from_location) { create :location, suppliers: [supplier] }
+    let(:to_location) { create :location, :court }
+    let(:person) { create(:person) }
+    let(:reason) { create(:prison_transfer_reason) }
+    let(:supplier) { create(:supplier) }
+    let(:data) do
+      {
+        type: 'moves',
+        attributes: move_attributes,
+        relationships: {
+          person: { data: { type: 'people', id: person.id } },
+          from_location: { data: { type: 'locations', id: from_location.id } },
+          to_location: to_location ? { data: { type: 'locations', id: to_location.id } } : { data: nil },
+          prison_transfer_reason: { data: { type: 'prison_transfer_reasons', id: reason.id } },
+        },
+      }
+    end
+
+    before { post '/api/moves', params: { data: }, headers:, as: :json }
+
+    it 'logs the correct response code' do
+      expect(access_log.code).to eq('201')
+    end
+
+    context 'when invalid move type' do
+      let(:move_attributes) do
+        {
+          date: Time.zone.today,
+          time_due: Time.zone.now,
+          status: 'requested',
+          additional_information: 'some more info',
+          move_type: 'wrong',
+        }
+      end
+
+      it 'logs the correct response code' do
+        expect(access_log.code).to eq('422')
+      end
+    end
+
+    context 'when invalid status' do
+      let(:move_attributes) do
+        {
+          date: Time.zone.today,
+          time_due: Time.zone.now,
+          status: 'blahblah',
+          additional_information: 'some more info',
+          move_type: 'court_appearance',
+        }
+      end
+
+      it 'logs the correct response code' do
+        expect(access_log.code).to eq('422')
+      end
+    end
+  end
+end