Log response body to production_json.log when a controller responds with a 422 status

We have a number of import errors occurring with 422 errors, and
it's hard to determine why they are happening. This change will
surface the errors in the log lines.

Relates to #47365

app/controllers/application_controller.rb

@@ -91,6 +91,10 @@ class ApplicationController < ActionController::Base
       payload[:user_id] = logged_user.try(:id)
       payload[:username] = logged_user.try(:username)
     end
+
+    if response.status == 422 && response.body.present? && response.content_type == 'application/json'.freeze
+      payload[:response] = response.body
+    end
   end
 
   # Controllers such as GitHttpController may use alternative methods

changelogs/unreleased/sh-log-422-responses.yml

@@ -0,0 +1,6 @@
+---
+title: Log response body to production_json.log when a controller responds with a
+  422 status
+merge_request:
+author:
+type: other

config/initializers/lograge.rb

@@ -27,6 +27,7 @@ unless Sidekiq.server?
 
       gitaly_calls = Gitlab::GitalyClient.get_request_count
       payload[:gitaly_calls] = gitaly_calls if gitaly_calls > 0
+      payload[:response] = event.payload[:response] if event.payload[:response]
 
       payload
     end

spec/controllers/application_controller_spec.rb

@@ -1,3 +1,4 @@
+# coding: utf-8
 require 'spec_helper'
 
 describe ApplicationController do
@@ -478,6 +479,63 @@ describe ApplicationController do
     end
   end
 
+  describe '#append_info_to_payload' do
+    controller(described_class) do
+      attr_reader :last_payload
+
+      def index
+        render text: 'authenticated'
+      end
+
+      def append_info_to_payload(payload)
+        super
+
+        @last_payload = payload
+      end
+    end
+
+    it 'does not log errors with a 200 response' do
+      get :index
+
+      expect(controller.last_payload.has_key?(:response)).to be_falsey
+    end
+
+    context '422 errors' do
+      it 'logs a response with a string' do
+        response = spy(ActionDispatch::Response, status: 422, body: 'Hello world', content_type: 'application/json')
+        allow(controller).to receive(:response).and_return(response)
+        get :index
+
+        expect(controller.last_payload[:response]).to eq('Hello world')
+      end
+
+      it 'logs a response with an array' do
+        body = ['I want', 'my hat back']
+        response = spy(ActionDispatch::Response, status: 422, body: body, content_type: 'application/json')
+        allow(controller).to receive(:response).and_return(response)
+        get :index
+
+        expect(controller.last_payload[:response]).to eq(body)
+      end
+
+      it 'does not log a string with an empty body' do
+        response = spy(ActionDispatch::Response, status: 422, body: nil, content_type: 'application/json')
+        allow(controller).to receive(:response).and_return(response)
+        get :index
+
+        expect(controller.last_payload.has_key?(:response)).to be_falsey
+      end
+
+      it 'does not log an HTML body' do
+        response = spy(ActionDispatch::Response, status: 422, body: 'This is a test', content_type: 'application/html')
+        allow(controller).to receive(:response).and_return(response)
+        get :index
+
+        expect(controller.last_payload.has_key?(:response)).to be_falsey
+      end
+    end
+  end
+
   describe '#access_denied' do
     controller(described_class) do
       def index