diff --git a/changelogs/unreleased/sh-log-api-errors.yml b/changelogs/unreleased/sh-log-api-errors.yml new file mode 100644 index 000000000000..eeeca6c4de6f --- /dev/null +++ b/changelogs/unreleased/sh-log-api-errors.yml @@ -0,0 +1,5 @@ +--- +title: Log server responses of API bad requests in api_json.log +merge_request: 29839 +author: +type: other diff --git a/lib/api/helpers.rb b/lib/api/helpers.rb index 42b82aac1c43..5ce3353b7342 100644 --- a/lib/api/helpers.rb +++ b/lib/api/helpers.rb @@ -11,6 +11,7 @@ module Helpers 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 @@ def render_spam_error! 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 diff --git a/lib/gitlab/grape_logging/loggers/exception_logger.rb b/lib/gitlab/grape_logging/loggers/exception_logger.rb index 606b7c0dbce7..14147769422b 100644 --- a/lib/gitlab/grape_logging/loggers/exception_logger.rb +++ b/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 @@ def parameters(request, _) 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 diff --git a/spec/lib/gitlab/grape_logging/loggers/exception_logger_spec.rb b/spec/lib/gitlab/grape_logging/loggers/exception_logger_spec.rb index c9021e2f4368..cc9535d4d2c6 100644 --- a/spec/lib/gitlab/grape_logging/loggers/exception_logger_spec.rb +++ b/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 @@ 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 @@ end it 'includes the backtrace' do - expect(subject.parameters(mock_request, nil)).to eq(expected) + expect(subject).to eq(expected) end end end diff --git a/spec/requests/api/helpers_spec.rb b/spec/requests/api/helpers_spec.rb index 98904a4d79f6..d65c89f48ea5 100644 --- a/spec/requests/api/helpers_spec.rb +++ b/spec/requests/api/helpers_spec.rb @@ -328,6 +328,8 @@ def set_param(key, value) 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 @@ def set_param(key, value) 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