Log server responses of API bad requests in api_json.log

The API helper `render_api_error!` previously would log a 400 error with
no details in `api_json.log`, which made it difficult to debug problems
in production. To fix this, we:

1. Store the intended status code in the request
environment. grape-logging doesn't pass this along to the loggers:
https://github.com/aserafin/grape_logging/issues/71

2. In the logger, check the code. If it is 400, attach an `api_error`
field that contains the response from the server.

Closes https://gitlab.com/gitlab-org/gitlab/-/issues/214879

changelogs/unreleased/sh-log-api-errors.yml

+---
+title: Log server responses of API bad requests in api_json.log
+merge_request: 29839
+author:
+type: other

lib/api/helpers.rb

@@ -11,6 +11,7 @@ module API
     SUDO_PARAM = :sudo
     API_USER_ENV = 'gitlab.api.user'
     API_EXCEPTION_ENV = 'gitlab.api.exception'
+    API_RESPONSE_STATUS_CODE = 'gitlab.api.response_status_code'
 
     def declared_params(options = {})
       options = { include_parent_namespaces: false }.merge(options)
@@ -416,6 +417,11 @@ module API
     end
 
     def render_api_error!(message, status)
+      # grape-logging doesn't pass the status code, so this is a
+      # workaround for getting that information in the loggers:
+      # https://github.com/aserafin/grape_logging/issues/71
+      env[API_RESPONSE_STATUS_CODE] = Rack::Utils.status_code(status)
+
       error!({ 'message' => message }, status, header)
     end
 

lib/gitlab/grape_logging/loggers/exception_logger.rb

@@ -4,14 +4,16 @@ module Gitlab
   module GrapeLogging
     module Loggers
       class ExceptionLogger < ::GrapeLogging::Loggers::Base
-        def parameters(request, _)
+        def parameters(request, response_body)
+          data = {}
+          data[:api_error] = format_body(response_body) if bad_request?(request)
+
           # grape-logging attempts to pass the logger the exception
           # (https://github.com/aserafin/grape_logging/blob/v1.7.0/lib/grape_logging/middleware/request_logger.rb#L63),
           # but it appears that the rescue_all in api.rb takes
           # precedence so the logger never sees it. We need to
           # store and retrieve the exception from the environment.
           exception = request.env[::API::Helpers::API_EXCEPTION_ENV]
-          data = {}
 
           return data unless exception.is_a?(Exception)
 
@@ -19,6 +21,28 @@ module Gitlab
 
           data
         end
+
+        private
+
+        def format_body(response_body)
+          # https://github.com/rack/rack/blob/master/SPEC.rdoc#label-The+Body:
+          # The response_body must respond to each, but just in case we
+          # guard against errors here.
+          response_body = Array(response_body) unless response_body.respond_to?(:each)
+
+          # To avoid conflicting types in Elasticsearch, convert every
+          # element into an Array of strings. A response body is usually
+          # an array of Strings so that the response can be sent in
+          # chunks.
+          body = []
+          # each_with_object doesn't work with Rack::BodyProxy
+          response_body.each { |chunk| body << chunk.to_s }
+          body
+        end
+
+        def bad_request?(request)
+          request.env[::API::Helpers::API_RESPONSE_STATUS_CODE] == 400
+        end
       end
     end
   end

spec/lib/gitlab/grape_logging/loggers/exception_logger_spec.rb

@@ -3,14 +3,73 @@
 require 'spec_helper'
 
 describe Gitlab::GrapeLogging::Loggers::ExceptionLogger do
-  subject { described_class.new }
-
   let(:mock_request) { OpenStruct.new(env: {}) }
+  let(:response_body) { nil }
 
   describe ".parameters" do
+    subject { described_class.new.parameters(mock_request, response_body) }
+
     describe 'when no exception is available' do
       it 'returns an empty hash' do
-        expect(subject.parameters(mock_request, nil)).to eq({})
+        expect(subject).to eq({})
+      end
+    end
+
+    describe 'with a response' do
+      before do
+        mock_request.env[::API::Helpers::API_RESPONSE_STATUS_CODE] = code
+      end
+
+      context 'with a String response' do
+        let(:response_body) { { message: "something went wrong" }.to_json }
+        let(:code) { 400 }
+        let(:expected) { { api_error: [response_body.to_s] } }
+
+        it 'logs the response body' do
+          expect(subject).to eq(expected)
+        end
+      end
+
+      context 'with an Array response' do
+        let(:response_body) { ["hello world", 1] }
+        let(:code) { 400 }
+        let(:expected) { { api_error: ["hello world", "1"] } }
+
+        it 'casts all elements to strings' do
+          expect(subject).to eq(expected)
+        end
+      end
+
+      # Rack v2.0.9 can return a BodyProxy. This was changed in later versions:
+      # https://github.com/rack/rack/blob/2.0.9/lib/rack/response.rb#L69
+      context 'with a Rack BodyProxy response' do
+        let(:message) { { message: "something went wrong" }.to_json }
+        let(:response) { Rack::Response.new(message, code, {}) }
+        let(:response_body) { Rack::BodyProxy.new(response) }
+        let(:code) { 400 }
+        let(:expected) { { api_error: [message] } }
+
+        it 'logs the response body' do
+          expect(subject).to eq(expected)
+        end
+      end
+
+      context 'unauthorized error' do
+        let(:response_body) { 'unauthorized' }
+        let(:code) { 401 }
+
+        it 'does not log an api_error field' do
+          expect(subject).not_to have_key(:api_error)
+        end
+      end
+
+      context 'HTTP success' do
+        let(:response_body) { 'success' }
+        let(:code) { 200 }
+
+        it 'does not log an api_error field' do
+          expect(subject).not_to have_key(:api_error)
+        end
       end
     end
 
@@ -32,7 +91,7 @@ describe Gitlab::GrapeLogging::Loggers::ExceptionLogger do
       end
 
       it 'returns the correct fields' do
-        expect(subject.parameters(mock_request, nil)).to eq(expected)
+        expect(subject).to eq(expected)
       end
 
       context 'with backtrace' do
@@ -43,7 +102,7 @@ describe Gitlab::GrapeLogging::Loggers::ExceptionLogger do
         end
 
         it 'includes the backtrace' do
-          expect(subject.parameters(mock_request, nil)).to eq(expected)
+          expect(subject).to eq(expected)
         end
       end
     end

spec/requests/api/helpers_spec.rb

@@ -328,6 +328,8 @@ describe API::Helpers do
 
       it 'returns a 401 response' do
         expect { authenticate! }.to raise_error /401/
+
+        expect(env[described_class::API_RESPONSE_STATUS_CODE]).to eq(401)
       end
     end
 
@@ -340,6 +342,8 @@ describe API::Helpers do
 
       it 'does not raise an error' do
         expect { authenticate! }.not_to raise_error
+
+        expect(env[described_class::API_RESPONSE_STATUS_CODE]).to be_nil
       end
     end
   end