diff --git a/Gemfile.lock b/Gemfile.lock index 6e0c732..cac887f 100644 --- a/Gemfile.lock +++ b/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) diff --git a/lib/entitlements/service/github.rb b/lib/entitlements/service/github.rb index ec9af19..0a977a9 100644 --- a/lib/entitlements/service/github.rb +++ b/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 diff --git a/lib/version.rb b/lib/version.rb index 34d3bc2..412c637 100644 --- a/lib/version.rb +++ b/lib/version.rb @@ -2,6 +2,6 @@ module Entitlements module Version - VERSION = "1.2.0" + VERSION = "1.2.1" end end diff --git a/spec/acceptance/docker-compose.yml b/spec/acceptance/docker-compose.yml index c778e7e..1672f22 100644 --- a/spec/acceptance/docker-compose.yml +++ b/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: diff --git a/spec/acceptance/ldap-server/env/default.startup.yaml b/spec/acceptance/ldap-server/env/default.startup.yaml index ace4399..d0c8667 100644 --- a/spec/acceptance/ldap-server/env/default.startup.yaml +++ b/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 diff --git a/spec/acceptance/ldap-server/ldif/data/99-bind-account/emmy.ldif b/spec/acceptance/ldap-server/ldif/data/99-bind-account/emmy.ldif index 3cf9020..87e908e 100644 --- a/spec/acceptance/ldap-server/ldif/data/99-bind-account/emmy.ldif +++ b/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 - diff --git a/spec/acceptance/ldap-server/run-server.sh b/spec/acceptance/ldap-server/run-server.sh index 7ededa9..b86648a 100755 --- a/spec/acceptance/ldap-server/run-server.sh +++ b/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 diff --git a/spec/unit/entitlements/service/github_spec.rb b/spec/unit/entitlements/service/github_spec.rb index fe7b025..eea708e 100644 --- a/spec/unit/entitlements/service/github_spec.rb +++ b/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,7 +368,7 @@ 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") @@ -376,16 +376,23 @@ 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!\"") @@ -393,10 +400,10 @@ 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