We should only WARN on http codes we intend to retry on

Gemfile.lock

@@ -1,7 +1,7 @@
 PATH
   remote: .
   specs:
-    entitlements-github-plugin (1.2.0)
+    entitlements-github-plugin (1.2.1)
       contracts (~> 0.17.0)
       faraday (~> 2.0)
       faraday-retry (~> 2.0)

lib/entitlements/service/github.rb

@@ -338,10 +338,10 @@ def pending_members_from_graphql
       def graphql_http_post(query)
         1.upto(MAX_GRAPHQL_RETRIES) do |try_number|
           result = graphql_http_post_real(query)
-          if result[:code] < 500
+          if !graphql_result_retryable?(result)
             return result
           elsif try_number >= MAX_GRAPHQL_RETRIES
-            Entitlements.logger.error "Query still failing after #{MAX_GRAPHQL_RETRIES} tries. Giving up."
+            Entitlements.logger.error "Query still failing after #{MAX_GRAPHQL_RETRIES} tries (last code: #{result[:code]}). Giving up."
             return result
           else
             Entitlements.logger.warn "GraphQL failed on try #{try_number} of #{MAX_GRAPHQL_RETRIES}. Will retry."
@@ -350,6 +350,18 @@ def graphql_http_post(query)
         end
       end
 
+      # Helper: determine whether a result hash from `graphql_http_post_real` represents
+      # a transient failure that the retry wrapper will retry. Used by the wrapper itself
+      # and to decide log severity inside `graphql_http_post_real`.
+      #
+      # result - Hash returned by `graphql_http_post_real`.
+      #
+      # Returns true if the result is retryable (HTTP 5xx or synthetic 5xx), false otherwise.
+      Contract ({ code: Integer, data: C::Or[nil, Hash] }) => C::Bool
+      def graphql_result_retryable?(result)
+        result[:code] >= 500
+      end
+
       # Helper method: Do the HTTP POST to the GitHub API for GraphQL.
       #
       # query - String with the data to be posted.
@@ -370,23 +382,35 @@ def graphql_http_post_real(query)
           response = http.request(request)
 
           if response.code != "200"
-            Entitlements.logger.error "Got HTTP #{response.code} POSTing to #{uri}"
-            Entitlements.logger.error response.body
+            # The retry wrapper retries on 5xx, so log those at WARN to avoid misleading
+            # the operator with an ERROR for a transient failure that we recover from.
+            # Terminal non-2xx responses (4xx) stay at ERROR.
+            msg = "POST to #{uri} returned HTTP Code #{response.code} and Body: #{response.body}"
+            response.code.start_with?("5") ? Entitlements.logger.warn(msg) : Entitlements.logger.error(msg)
             return { code: response.code.to_i, data: { "body" => response.body } }
           end
 
           begin
             data = JSON.parse(response.body)
             if data.key?("errors")
-              Entitlements.logger.error "Errors reported: #{data['errors'].inspect}"
+              # 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 } }
           end
         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
+          # branch can mask programming errors that operators must see.
           Entitlements.logger.error "Caught #{e.class} POSTing to #{uri}: #{e.message}"
           { code: 500, data: nil }
         end

lib/version.rb

@@ -2,6 +2,6 @@
 
 module Entitlements
   module Version
-    VERSION = "1.2.0"
+    VERSION = "1.2.1"
   end
 end

spec/acceptance/docker-compose.yml

@@ -31,7 +31,7 @@ services:
 
   ldap-server:
     entrypoint: /acceptance/ldap-server/run-server.sh
-    image: osixia/openldap:1.2.2
+    image: osixia/openldap:2.6.10-alpha
     networks:
       ldap-network:
         aliases:

spec/unit/entitlements/service/github_spec.rb

@@ -352,7 +352,7 @@
       expect_any_instance_of(Object).to receive(:sleep).with(2).exactly(1).times
       expect(logger).to receive(:warn).with("GraphQL failed on try 1 of 3. Will retry.")
       expect(logger).to receive(:warn).with("GraphQL failed on try 2 of 3. Will retry.")
-      expect(logger).to receive(:error).with("Query still failing after 3 tries. Giving up.")
+      expect(logger).to receive(:error).with("Query still failing after 3 tries (last code: 502). Giving up.")
 
       response = subject.send(:graphql_http_post, query)
       expect(response[:code]).to eq(502)
@@ -368,35 +368,42 @@
       expect(response).to eq(code: 200, data: answer)
     end
 
-    it "logs and returns code=500 and exception message for an unhandled exception" do
+    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)
       expect(logger).to receive(:error).with("Caught StandardError POSTing to https://github.fake/api/v3/graphql: Oh no you don't")
       response = subject.send(:graphql_http_post_real, "nonsense")
       expect(response).to eq(code: 500, data: nil)
     end
 
-    it "logs and returns code and body for non-200 response" do
+    it "logs at error and returns code and body for a non-200 4xx response" do
       answer = { "errors" => ["message" => "Something busted"] }
       stub_request(:post, "https://github.fake/api/v3/graphql").to_return(status: 429, body: JSON.generate(answer))
-      expect(logger).to receive(:error).with("Got HTTP 429 POSTing to https://github.fake/api/v3/graphql")
-      expect(logger).to receive(:error).with("{\"errors\":[{\"message\":\"Something busted\"}]}")
+      expect(logger).to receive(:error).with("POST to https://github.fake/api/v3/graphql returned HTTP Code 429 and Body: #{JSON.generate(answer)}")
       response = subject.send(:graphql_http_post_real, "nonsense")
       expect(response).to eq(code: 429, data: { "body" => JSON.generate(answer) })
     end
 
-    it "logs and returns raw text for JSON parsing error" do
+    it "logs at warn and returns code and body for a 5xx response (retryable)" do
+      body = '{"message": "We couldn\'t respond to your request in time. Sorry about that."}'
+      stub_request(:post, "https://github.fake/api/v3/graphql").to_return(status: 504, body:)
+      expect(logger).to receive(:warn).with("POST to https://github.fake/api/v3/graphql returned HTTP Code 504 and Body: #{body}")
+      response = subject.send(:graphql_http_post_real, "nonsense")
+      expect(response).to eq(code: 504, data: { "body" => body })
+    end
+
+    it "logs at error and returns raw text for JSON parsing error" do
       answer = "mor chicken mor rewardz!"
       stub_request(:post, "https://github.fake/api/v3/graphql").to_return(status: 200, body: answer)
       expect(logger).to receive(:error).with("JSON::ParserError unexpected character: 'mor' at line 1 column 1: \"mor chicken mor rewardz!\"")
       response = subject.send(:graphql_http_post_real, "nonsense")
       expect(response).to eq(code: 500, data: { "body" => "mor chicken mor rewardz!" })
     end
 
-    it "logs and returns when errors are reported in a 200" do
+    it "logs at warn and returns when errors are reported in a 200" do
       answer = { "errors" => ["ENOTENOUGHCHICKEn"] }
       stub_request(:post, "https://github.fake/api/v3/graphql").to_return(status: 200, body: JSON.generate(answer))
-      expect(logger).to receive(:error).with("Errors reported: [\"ENOTENOUGHCHICKEn\"]")
+      expect(logger).to receive(:warn).with("Errors reported: [\"ENOTENOUGHCHICKEn\"]")
       response = subject.send(:graphql_http_post_real, "nonsense")
       expect(response).to eq(code: 500, data: answer)
     end