Merge branch 'sh-log-422-responses' into 'master'2018-06-07-RC-cut

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

See merge request gitlab-org/gitlab-ce!19473

4 files changed, 69 insertions, 0 deletions

diff --git a/app/controllers/application_controller.rb b/app/controllers/application_controller.rb
index bc60a0a02e8..041837c5410 100644
--- a/app/controllers/application_controller.rb
+++ b/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
diff --git a/changelogs/unreleased/sh-log-422-responses.yml b/changelogs/unreleased/sh-log-422-responses.yml
new file mode 100644
index 00000000000..c7dfdbb703b
--- /dev/null
+++ b/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
diff --git a/config/initializers/lograge.rb b/config/initializers/lograge.rb
index 114c1cb512f..1cf8a24e98c 100644
--- a/config/initializers/lograge.rb
+++ b/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
diff --git a/spec/controllers/application_controller_spec.rb b/spec/controllers/application_controller_spec.rb
index 683c57c96f8..773bf25ed44 100644
--- a/spec/controllers/application_controller_spec.rb
+++ b/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