From b079242cb6a8311535c37ecc1761e7b0b1e3dcd4 Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 14:53:26 -0500 Subject: [PATCH 1/7] We should only WARN on http codes we intend to retry on --- lib/entitlements/service/github.rb | 51 ++++++++++++++++--- spec/unit/entitlements/service/github_spec.rb | 23 ++++++--- 2 files changed, 61 insertions(+), 13 deletions(-) diff --git a/lib/entitlements/service/github.rb b/lib/entitlements/service/github.rb index ec9af19..2a3d748 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,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 diff --git a/spec/unit/entitlements/service/github_spec.rb b/spec/unit/entitlements/service/github_spec.rb index fe7b025..0978453 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,7 +376,7 @@ 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 From 54f8b513d516a50f6499cb187598cef1057f1efc Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 14:55:43 -0500 Subject: [PATCH 2/7] Bump the version for the minor bug fix --- lib/version.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 From f737e33f4722fbf372f35fe3dee3b44477cfa2a9 Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 15:00:59 -0500 Subject: [PATCH 3/7] We should return ERROR for JSON errors --- Gemfile.lock | 2 +- lib/entitlements/service/github.rb | 6 ++++-- spec/unit/entitlements/service/github_spec.rb | 4 ++-- 3 files changed, 7 insertions(+), 5 deletions(-) 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 2a3d748..0eabd21 100644 --- a/lib/entitlements/service/github.rb +++ b/lib/entitlements/service/github.rb @@ -418,8 +418,10 @@ def graphql_http_post_real(query) end { code: response.code.to_i, data: } rescue JSON::ParserError => e - # Synthesized 500 below triggers a retry; log at WARN. - Entitlements.logger.warn "#{e.class} #{e.message}: #{response.body.inspect}" + # 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 diff --git a/spec/unit/entitlements/service/github_spec.rb b/spec/unit/entitlements/service/github_spec.rb index 0978453..15e2b74 100644 --- a/spec/unit/entitlements/service/github_spec.rb +++ b/spec/unit/entitlements/service/github_spec.rb @@ -394,10 +394,10 @@ expect(response).to eq(code: 504, data: { "body" => body }) end - it "logs at warn and returns raw text for JSON parsing error" do + 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(:warn).with("JSON::ParserError unexpected character: 'mor' at line 1 column 1: \"mor chicken mor rewardz!\"") + 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 From bbc60de2d6e0ad2f606473600858adc244d952e8 Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 15:08:25 -0500 Subject: [PATCH 4/7] move to a more recent LDAP server for acceptance testing --- spec/acceptance/docker-compose.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/acceptance/docker-compose.yml b/spec/acceptance/docker-compose.yml index c778e7e..11f5c80 100644 --- a/spec/acceptance/docker-compose.yml +++ b/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: From c555b9acf6e3bf60d7c379c707f1136e40b2db31 Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 16:02:52 -0500 Subject: [PATCH 5/7] Don't over complicate things with needless abstraction methods --- lib/entitlements/service/github.rb | 21 ++----------------- spec/unit/entitlements/service/github_spec.rb | 6 ++---- 2 files changed, 4 insertions(+), 23 deletions(-) diff --git a/lib/entitlements/service/github.rb b/lib/entitlements/service/github.rb index 0eabd21..0a977a9 100644 --- a/lib/entitlements/service/github.rb +++ b/lib/entitlements/service/github.rb @@ -362,22 +362,6 @@ 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. @@ -401,9 +385,8 @@ def graphql_http_post_real(query) # 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) + 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 diff --git a/spec/unit/entitlements/service/github_spec.rb b/spec/unit/entitlements/service/github_spec.rb index 15e2b74..eea708e 100644 --- a/spec/unit/entitlements/service/github_spec.rb +++ b/spec/unit/entitlements/service/github_spec.rb @@ -379,8 +379,7 @@ 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 @@ -388,8 +387,7 @@ 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) + 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 From 4e534b37b2c5c2d9ee5b2da2cc6b62978bf5976e Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 16:26:36 -0500 Subject: [PATCH 6/7] Fighting with LDAP is not the fight I want to have today --- spec/acceptance/docker-compose.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/spec/acceptance/docker-compose.yml b/spec/acceptance/docker-compose.yml index 11f5c80..b44a9a8 100644 --- a/spec/acceptance/docker-compose.yml +++ b/spec/acceptance/docker-compose.yml @@ -31,7 +31,7 @@ services: ldap-server: entrypoint: /acceptance/ldap-server/run-server.sh - image: osixia/openldap:2.6.10-alpha + image: osixia/openldap:1.5.0 networks: ldap-network: aliases: From 2c073b2b92150ab9d81feb51d44c7cb2b6f067a1 Mon Sep 17 00:00:00 2001 From: John Northrup Date: Tue, 5 May 2026 17:02:37 -0500 Subject: [PATCH 7/7] Make it work with OpenLDAP 1.5.0 --- spec/acceptance/docker-compose.yml | 2 -- .../ldap-server/env/default.startup.yaml | 3 ++- .../ldif/data/99-bind-account/emmy.ldif | 2 +- spec/acceptance/ldap-server/run-server.sh | 19 ++++++++++++++----- 4 files changed, 17 insertions(+), 9 deletions(-) diff --git a/spec/acceptance/docker-compose.yml b/spec/acceptance/docker-compose.yml index b44a9a8..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 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