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

Author: northrup

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,34 @@ 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: log `message` to `Entitlements.logger` at the given severity. Restricts
+      # the dispatch to a known set of severities so callers can pick a level computed
+      # at runtime without going through `send`/`public_send`.
+      #
+      # severity - Symbol, one of :warn or :error.
+      # message  - String message to log.
+      #
+      # Returns nothing.
+      Contract C::Or[:warn, :error], String => C::Any
+      def log_at_severity(severity, message)
+        case severity
+        when :warn then Entitlements.logger.warn(message)
+        when :error then Entitlements.logger.error(message)
+        end
+      end
+
       # Helper method: Do the HTTP POST to the GitHub API for GraphQL.
       #
       # query - String with the data to be posted.
@@ -370,23 +398,34 @@ 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.
+            severity = response.code.start_with?("5") ? :warn : :error
+            log_at_severity(severity, "Got HTTP #{response.code} POSTing to #{uri}")
+            log_at_severity(severity, response.body)
             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
-            Entitlements.logger.error "#{e.class} #{e.message}: #{response.body.inspect}"
+            # Synthesized 500 below triggers a retry; log at WARN.
+            Entitlements.logger.warn "#{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

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,15 +368,15 @@
       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")
@@ -385,18 +385,27 @@
       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("Got HTTP 504 POSTing to https://github.fake/api/v3/graphql")
+      expect(logger).to receive(:warn).with(body)
+      response = subject.send(:graphql_http_post_real, "nonsense")
+      expect(response).to eq(code: 504, data: { "body" => body })
+    end
+
+    it "logs at warn 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!\"")
+      expect(logger).to receive(:warn).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