diff --git a/Gemfile.lock b/Gemfile.lock index 9019485..e5e595e 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -1,7 +1,7 @@ PATH remote: . specs: - entitlements-github-plugin (1.2.5) + entitlements-github-plugin (1.2.6) contracts (~> 0.17.0) faraday (~> 2.0) faraday-net_http_persistent (~> 2.3) diff --git a/lib/entitlements/service/github.rb b/lib/entitlements/service/github.rb index e0e06b2..7743a68 100644 --- a/lib/entitlements/service/github.rb +++ b/lib/entitlements/service/github.rb @@ -392,23 +392,29 @@ def graphql_http_post_real(query) return { code: response.code.to_i, data: { "body" => response.body } } end - begin - data = JSON.parse(response.body) - if data.key?("errors") - # Synthesized 500 below triggers a retry, so log at WARN. Note: some GraphQL - # `errors` are permanent (bad query, auth, schema). The retry wrapper's final - # "Giving up" ERROR will surface persistent cases. - Entitlements.logger.warn "Errors reported: #{data['errors'].inspect}" - return { code: 500, data: } - end - { code: response.code.to_i, data: } - rescue JSON::ParserError => e - # JSON parse errors mean the API returned something we can't interpret. The - # synthesized 500 below triggers a retry, but the cause is more likely a real - # protocol/server problem than a transient network blip, so log at ERROR. - Entitlements.logger.error "#{e.class} #{e.message}: #{response.body.inspect}" - { code: 500, data: { "body" => response.body } } + data = JSON.parse(response.body) + if data.key?("errors") + # Synthesized 500 below triggers a retry, so log at WARN. Note: some GraphQL + # `errors` are permanent (bad query, auth, schema). The retry wrapper's final + # "Giving up" ERROR will surface persistent cases. + Entitlements.logger.warn "Errors reported: #{data['errors'].inspect}" + return { code: 500, data: } end + + { code: response.code.to_i, data: } + + rescue Net::ReadTimeout => e + # Defend against network blips, those can be safely retried via the + # synthesized 500 below, so log at WARN. + reset_graphql_http + Entitlements.logger.warn "#{e.class} #{e.message}" + { code: 500, data: nil } + rescue JSON::ParserError => e + # JSON parse errors mean the API returned something we can't interpret. The + # synthesized 500 below triggers a retry, but the cause is more likely a real + # protocol/server problem than a transient network blip, so log at ERROR. + Entitlements.logger.error "#{e.class} #{e.message}: #{response.body.inspect}" + { code: 500, data: { "body" => response.body } } rescue => e # Catch-all for any unexpected exception (network blip OR local code bug). # We retry below via the synthesized 500, but log at ERROR because this diff --git a/lib/version.rb b/lib/version.rb index 0dd6539..7f933cc 100644 --- a/lib/version.rb +++ b/lib/version.rb @@ -2,6 +2,6 @@ module Entitlements module Version - VERSION = "1.2.5" + VERSION = "1.2.6" end end diff --git a/spec/unit/entitlements/service/github_spec.rb b/spec/unit/entitlements/service/github_spec.rb index 4403a94..27defea 100644 --- a/spec/unit/entitlements/service/github_spec.rb +++ b/spec/unit/entitlements/service/github_spec.rb @@ -340,9 +340,9 @@ expect(replacement_http).to receive(:start) expect(replacement_http).to receive(:request).and_return(response) expect_any_instance_of(Object).to receive(:sleep).with(1).once - expect(logger).to receive(:error). - with("Caught Net::ReadTimeout POSTing to https://github.fake/api/v3/graphql: Net::ReadTimeout with \"execution expired\"") - expect(logger).to receive(:warn). + expect(logger).to receive(:warn).ordered. + with("Net::ReadTimeout Net::ReadTimeout with \"execution expired\"") + expect(logger).to receive(:warn).ordered. with("GraphQL failed on try 1 of 3. Will retry.") expect(subject.send(:graphql_http_post, query)).to eq(code: 200, data: answer) @@ -450,6 +450,14 @@ expect(response).to eq(code: 200, data: answer) end + it "logs at warn and returns a retryable response for a read timeout" do + timeout = Net::ReadTimeout.new + stub_request(:post, "https://github.fake/api/v3/graphql").to_raise(timeout) + expect(logger).to receive(:warn).with("#{timeout.class} #{timeout.message}") + response = subject.send(:graphql_http_post_real, "nonsense") + expect(response).to eq(code: 500, data: nil) + end + it "logs at error and returns code=500 and exception message for an unhandled exception" do exc = StandardError.new("Oh no you don't") stub_request(:post, "https://github.fake/api/v3/graphql").to_raise(exc)