Merge pull request #259 from github/warn-on-500s

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

Author: northrup

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

@@ -1,5 +1,3 @@
-version: '2'
-
 networks:
   ldap-network:
     internal: true
@@ -31,7 +29,7 @@ services:
 
   ldap-server:
     entrypoint: /acceptance/ldap-server/run-server.sh
-    image: osixia/openldap:1.2.2
+    image: osixia/openldap:1.5.0
     networks:
       ldap-network:
         aliases:

spec/acceptance/ldap-server/env/default.startup.yaml

@@ -21,13 +21,14 @@ LDAP_READONLY_USER_PASSWORD: readonly
 LDAP_RFC2307BIS_SCHEMA: false
 
 # Backend
-LDAP_BACKEND: hdb
+LDAP_BACKEND: mdb
 
 # Tls
 LDAP_TLS: true
 LDAP_TLS_CRT_FILENAME: ldap.crt
 LDAP_TLS_KEY_FILENAME: ldap.key
 LDAP_TLS_CA_CRT_FILENAME: ca.crt
+LDAP_TLS_DH_PARAM_FILENAME: dhparam.pem
 
 LDAP_TLS_ENFORCE: true
 LDAP_TLS_CIPHER_SUITE: SECURE256:+SECURE128:-VERS-TLS-ALL:+VERS-TLS1.2:-RSA:-DHE-DSS:-CAMELLIA-128-CBC:-CAMELLIA-256-CBC

spec/acceptance/ldap-server/ldif/data/99-bind-account/emmy.ldif

@@ -8,7 +8,7 @@ objectClass: simpleSecurityObject
 uid: emmy
 userpassword: kittens
 
-dn: olcDatabase={1}hdb,cn=config
+dn: olcDatabase={1}mdb,cn=config
 changetype: modify
 delete: olcAccess
 -

spec/acceptance/ldap-server/run-server.sh

@@ -37,19 +37,28 @@ cp /acceptance/ca/intermediate/certs/ca-chain.cert.pem /container/service/slapd/
 cp /acceptance/ldap-server/tls/dhparam.pem /container/service/slapd/assets/certs/dhparam.pem
 chown -R root:root /container/service/slapd/assets/certs
 
-# Pre-install our configuration environment
-rm -f /container/environment/99-default/*.yaml
-cp /acceptance/ldap-server/env/*.yaml /container/environment/99-default
+# Pre-install our configuration environment.
+# Drop our overrides into a lexically earlier directory than the image's stock
+# /container/environment/99-default. osixia's run tool walks /container/environment
+# in sorted order and first-set-wins (see /container/tool/run), so values declared
+# here take precedence while everything we *don't* override (LDAP_PORT, LDAPS_PORT,
+# LDAP_NOFILE, DISABLE_CHOWN, etc.) is inherited from the image defaults.
+mkdir -p /container/environment/01-custom
+cp /acceptance/ldap-server/env/*.yaml /container/environment/01-custom/
 
 # Pre-install our schema (after killing most of the defaults from the container)
 rm -f /container/service/slapd/assets/config/bootstrap/ldif/0[345]*.ldif
 rm -rf /container/service/slapd/assets/config/bootstrap/schema/mmc
-rm -f /etc/ldap/schema/*
+# Only remove stock *.ldif schemas; keep *.schema files because osixia/openldap:1.5.0's
+# bootstrap (slaptest) converts *.schema -> cn=config and needs core.schema to exist.
+rm -f /etc/ldap/schema/*.ldif
 cp /acceptance/ldap-server/schema/* /etc/ldap/schema/
 cp /acceptance/ldap-server/ldif/bootstrap/*.ldif /container/service/slapd/assets/config/bootstrap/ldif
 
 # Launch openldap
-nohup /usr/bin/python -u /container/tool/run -l info &
+# /container/tool/run has its own `#!/usr/bin/python3 -u` shebang in osixia/openldap:1.5.0,
+# which no longer ships /usr/bin/python. Invoke it directly so we don't depend on Py2 paths.
+nohup /container/tool/run -l info &
 OPENLDAP_PID=$!
 
 # Wait for the process to be running and connectable

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