From d14c84d7e5c9acadb90b1cf90623dfc19939ea54 Mon Sep 17 00:00:00 2001 From: Greg Date: Wed, 8 Jul 2026 16:11:23 -0600 Subject: [PATCH] Back off QIT 429 retries in CLI --- src/src/RemoteTestRunner.php | 45 ++-- src/src/RequestBuilder.php | 204 ++++++++++++++---- src/tests/unit/RemoteTestRunnerPollTest.php | 43 ++++ .../unit/RequestBuilderHttpStatusTest.php | 27 +++ src/tests/unit/RequestBuilderTest.php | 70 ++++++ 5 files changed, 336 insertions(+), 53 deletions(-) create mode 100644 src/tests/unit/RemoteTestRunnerPollTest.php diff --git a/src/src/RemoteTestRunner.php b/src/src/RemoteTestRunner.php index 2cf6a8870..7dd6e6d32 100644 --- a/src/src/RemoteTestRunner.php +++ b/src/src/RemoteTestRunner.php @@ -307,11 +307,12 @@ private function wait_for_completion( InputInterface $input, OutputInterface $ou $is_json = $input->getOption( 'json' ); /** @var ConsoleSectionOutput|null $section */ - $section = null; - $last_result = null; - $last_status = ''; - $completed = false; - $ticks = 0; + $section = null; + $last_result = null; + $last_status = ''; + $completed = false; + $ticks = 0; + $poll_failures = 0; if ( $is_ci || $is_json ) { if ( ! $is_json ) { @@ -354,17 +355,23 @@ private function wait_for_completion( InputInterface $input, OutputInterface $ou if ( $ticks >= $poll_interval || $last_result === null ) { try { - $result_json = ( new RequestBuilder( get_manager_url() . '/wp-json/cd/v1/get-single' ) ) + $result_json = ( new RequestBuilder( get_manager_url() . '/wp-json/cd/v1/get-single' ) ) ->with_method( 'POST' ) ->with_post_body( [ 'test_run_id' => $test_run_id ] ) ->request(); - $last_result = json_decode( $result_json, true ); - $ticks = 0; + $last_result = json_decode( $result_json, true ); + $ticks = 0; + $poll_failures = 0; } catch ( \Exception $e ) { - if ( $last_result === null ) { - sleep( 1 ); - continue; - } + // A failed poll must not turn into a once-per-second burst (QIT-991): + // back off with jitter and reset the tick counter so the next attempt + // waits a proper interval. This applies both before the first result + // (previously a tight sleep(1) loop) and after a later failure + // (previously left $ticks >= $poll_interval, re-polling every second). + ++$poll_failures; + $ticks = 0; + sleep( self::poll_retry_delay( $poll_failures, $poll_interval ) ); + continue; } $completed = isset( $last_result['update_complete'] ) && $last_result['update_complete'] === true; @@ -395,6 +402,20 @@ private function wait_for_completion( InputInterface $input, OutputInterface $ou return $exit_code; } + /** + * Backoff delay (seconds) for a failed status poll: exponential from 2s, capped at + * the normal poll interval, with jitter so parallel CI clients do not retry in lockstep. + * + * @param int $failures Consecutive poll failures so far (1-based). + * @param int $poll_interval The normal polling cadence, used as the backoff ceiling. + */ + private static function poll_retry_delay( int $failures, int $poll_interval ): int { + $delay = 2 ** min( max( 1, $failures ), 5 ); + $delay = min( $poll_interval, $delay ); + + return $delay + rand( 0, 5 ); + } + /** * @param ConsoleSectionOutput $section The console section output. * @param array $result The Manager test run result. diff --git a/src/src/RequestBuilder.php b/src/src/RequestBuilder.php index 793dd6d9f..32f8b9fb3 100644 --- a/src/src/RequestBuilder.php +++ b/src/src/RequestBuilder.php @@ -36,6 +36,13 @@ class RequestBuilder { /** @var int */ protected $retry_429 = 5; + /** + * Default number of 429 retries and the longest single wait (seconds) we will + * back off for. Shared between the API request path and the ZIP download path. + */ + protected const MAX_429_RETRIES = 5; + protected const MAX_429_WAIT_SECONDS = 180; + /** @var int */ protected $timeout_in_seconds = 30; @@ -175,6 +182,12 @@ public function with_file( string $field_name, string $file_path ): self { } public function request(): string { + // The 429 retry budget is per HTTP request. Reset it on entry so a reused builder + // (e.g. the same instance uploading every chunk in Upload.php) does not carry an + // exhausted budget from earlier chunks into later, otherwise-fresh requests. The + // reset is before the retry label so retries within this call still count down. + $this->retry_429 = static::MAX_429_RETRIES; + retry_request: // phpcs:ignore Generic.PHP.DiscourageGoto.Found // Apply rate limiting before making the request @@ -374,12 +387,33 @@ public function request(): string { $error_message = $body; $json_response = json_decode( $error_message, true ); - if ( is_array( $json_response ) && array_key_exists( 'message', $json_response ) ) { - $error_message = $json_response['message']; + // Prefer a structured error message. WordPress REST errors use `message`; + // our Manager rate-limit responses use `error`. + if ( is_array( $json_response ) ) { + if ( array_key_exists( 'message', $json_response ) ) { + $error_message = $json_response['message']; + } elseif ( array_key_exists( 'error', $json_response ) ) { + $error_message = $json_response['error']; + } } } if ( $response_status_code === 429 ) { + // If the server asked us to wait longer than we are willing to back off for, + // there is no point burning through capped retries that are guaranteed to 429 + // again. Fail immediately with clear, actionable guidance instead. + $retry_after_header = self::parse_retry_after_header( $headers ); + if ( ! is_null( $retry_after_header ) && $retry_after_header > static::MAX_429_WAIT_SECONDS ) { + throw new NetworkErrorException( + sprintf( + 'Rate limited by the server. Please wait about %d seconds (~%d minutes) and try again.', + $retry_after_header, + (int) ceil( $retry_after_header / 60 ) + ), + $response_status_code + ); + } + if ( $this->retry_429 > 0 ) { --$this->retry_429; $sleep_seconds = $this->wait_after_429( $headers ); @@ -466,7 +500,7 @@ public static function download_file( string $url, string $file_path ): void { } $mock_status = isset( $mocked['status'] ) ? (int) $mocked['status'] : 200; - self::assert_download_succeeded( $mock_status, $url, $file_path, $mocked['effective_url'] ?? null ); + self::finalize_download( $mock_status, $url, $file_path, $mocked['effective_url'] ?? null ); if ( $output->isVerbose() ) { $output->writeln( "Used mock response for $url, written to $file_path" ); @@ -523,12 +557,20 @@ public static function download_file( string $url, string $file_path ): void { ); } + $attempt = 0; + + download_attempt: // phpcs:ignore Generic.PHP.DiscourageGoto.Found + // Open file for writing, create it if it doesn't exist. $fp = fopen( $file_path, 'w' ); if ( $fp === false ) { throw new \RuntimeException( 'Could not open file for writing: ' . $file_path ); } + // Capture response headers separately so the error body (e.g. a 429 HTML page) + // is not mixed into the file we stream to disk, and so we can read Retry-After. + $response_headers = ''; + $curl = curl_init(); $curl_parameters = [ @@ -536,6 +578,11 @@ public static function download_file( string $url, string $file_path ): void { CURLOPT_RETURNTRANSFER => false, // Directly write the output. CURLOPT_FOLLOWLOCATION => true, CURLOPT_FILE => $fp, // Write the output to the file. + CURLOPT_HEADERFUNCTION => static function ( $ch, string $header_line ) use ( &$response_headers ): int { + $response_headers .= $header_line; + + return strlen( $header_line ); + }, ]; try { @@ -572,9 +619,63 @@ public static function download_file( string $url, string $file_path ): void { throw new \RuntimeException( 'Curl ' . $curl_error ); } + // The artifact ZIPs are served as static files behind the platform edge, which + // rate-limits with a 429 (an HTML page) rather than our JSON limiter. Retry with + // backoff instead of hard-failing on the first throttle. + if ( $http_code === 429 && $attempt < static::MAX_429_RETRIES ) { + $retry_after_header = self::parse_retry_after_header( $response_headers ); + + // Only retry when the wait is within our budget; a longer window is handled as a + // clean failure by finalize_download() below. + if ( is_null( $retry_after_header ) || $retry_after_header <= static::MAX_429_WAIT_SECONDS ) { + // Remove the partial error page before retrying. + self::delete_download_file( $file_path ); + + $delay = self::calculate_retry_delay( $retry_after_header, $attempt, static::MAX_429_WAIT_SECONDS ); + ++$attempt; + + if ( $output->isVerbose() ) { + $output->writeln( sprintf( + 'Download rate limited (429). Waiting %d seconds and retrying (%d/%d)...', + $delay, + $attempt, + static::MAX_429_RETRIES + ) ); + } + + sleep( $delay ); + goto download_attempt; // phpcs:ignore Generic.PHP.DiscourageGoto.Found + } + } + + self::finalize_download( $http_code, $url, $file_path, $effective_url ); + } + + /** + * Validate a completed download, translating a 429 into a clean rate-limit message + * (never leaking the raw HTML error page) and deferring all other statuses to + * assert_download_succeeded(). + */ + protected static function finalize_download( int $http_code, string $url, string $file_path, ?string $effective_url = null ): void { + if ( $http_code === 429 ) { + self::delete_download_file( $file_path ); + throw new \RuntimeException( self::download_rate_limited_message( $effective_url ?: $url ) ); + } + self::assert_download_succeeded( $http_code, $url, $file_path, $effective_url ); } + /** + * A user-facing message for a rate-limited download. Deliberately omits the response + * body so a 429 HTML page never ends up in the CLI output. + */ + protected static function download_rate_limited_message( string $url ): string { + return sprintf( + 'Download failed: rate limited (HTTP 429) for %s. Too many requests — please wait a few minutes and try again.', + self::sanitize_download_url_for_logs( $url ) + ); + } + /** * Validate a completed file download and remove unusable files before throwing. */ @@ -649,66 +750,87 @@ protected static function delete_download_file( string $file_path ): void { } } - protected function wait_after_429( string $headers, int $max_wait = 180 ): int { - $retry_after = null; + protected function wait_after_429( string $headers, int $max_wait = self::MAX_429_WAIT_SECONDS ): int { + $retry_after_header = self::parse_retry_after_header( $headers ); + + // Attempt number is derived from how many 429 retries we have consumed so far, + // so the exponential fallback grows as the counter is decremented (0-based). + $attempt = static::MAX_429_RETRIES - $this->retry_429; - // HTTP dates are always expressed in GMT, never in local time. (RFC 9110 5.6.7). - $gmt_timezone = new \DateTimeZone( 'GMT' ); + return self::calculate_retry_delay( $retry_after_header, $attempt, $max_wait ); + } - // HTTP headers are case-insensitive according to RFC 7230. - $headers = strtolower( $headers ); + /** + * Parse the server-provided Retry-After header into seconds. + * + * @param string $headers Raw response headers. + * + * @return int|null Seconds the server asked us to wait, or null if not provided/parseable. + * Never negative (a past date clamps to 0). + */ + protected static function parse_retry_after_header( string $headers ): ?int { + $retry_after = null; foreach ( explode( "\r\n", $headers ) as $header ) { /** - * Retry-After header is specified by RFC 9110 10.2.3 - * - * It can be formatted as http-date, or int (seconds). + * Retry-After is specified by RFC 9110 10.2.3 and can be an int (seconds) or an + * HTTP-date. Header names are case-insensitive (RFC 7230), so match with stripos + * anchored at the start of the line. * * Retry-After: Fri, 31 Dec 1999 23:59:59 GMT * Retry-After: 120 * * @link https://datatracker.ietf.org/doc/html/rfc9110#section-10.2.3 */ - if ( strpos( $header, 'retry-after:' ) !== false ) { - $retry_after_header = trim( substr( $header, strpos( $header, ':' ) + 1 ) ); + if ( stripos( $header, 'retry-after:' ) !== 0 ) { + continue; + } - // seconds. - if ( is_numeric( $retry_after_header ) ) { - $retry_after = intval( $retry_after_header ); - } else { - // Parse as HTTP-date in GMT timezone. - try { - $retry_after = ( new \DateTime( $retry_after_header, $gmt_timezone ) )->getTimestamp() - ( new \DateTime( 'now', $gmt_timezone ) )->getTimestamp(); - } catch ( \Exception $e ) { - $retry_after = null; - } - // http-date. - $retry_after_time = strtotime( $retry_after_header ); - if ( $retry_after_time !== false ) { - $retry_after = $retry_after_time - time(); - } - } + $value = trim( substr( $header, strpos( $header, ':' ) + 1 ) ); + if ( $value === '' ) { + continue; + } - if ( ! defined( 'UNIT_TESTS' ) ) { - App::make( Output::class )->writeln( sprintf( 'Got 429. Retrying after %d seconds...', $retry_after ) ); + if ( is_numeric( $value ) ) { + $retry_after = (int) $value; + } else { + // strtotime honors the timezone embedded in an HTTP-date (always GMT), + // so the delta against time() is correct regardless of local timezone. + $retry_after_time = strtotime( $value ); + if ( $retry_after_time !== false ) { + $retry_after = $retry_after_time - time(); } } } - // If no retry-after is specified, do a back-off. - if ( is_null( $retry_after ) ) { - $retry_after = 5 * pow( 2, abs( $this->retry_429 - 5 ) ); + if ( ! is_null( $retry_after ) && $retry_after < 0 ) { + $retry_after = 0; } - // Ensure we wait at least 1 second. - $retry_after = max( 1, $retry_after ); + return $retry_after; + } - // And no longer than 180 seconds. - $retry_after = min( $max_wait, $retry_after ); + /** + * Compute how long to sleep before a 429 retry: honor the server's Retry-After when + * present, otherwise exponential backoff. Always floored at 1s, capped at $max_wait, + * and given 0-5s of jitter so parallel clients do not retry in lockstep. + * + * @param int|null $retry_after_header Server-requested seconds, or null for backoff. + * @param int $attempt 0-based retry attempt number. + * @param int $max_wait Upper bound (seconds) on the returned delay. + */ + protected static function calculate_retry_delay( ?int $retry_after_header, int $attempt, int $max_wait = self::MAX_429_WAIT_SECONDS ): int { + if ( is_null( $retry_after_header ) ) { + $retry_after = 5 * pow( 2, max( 0, $attempt ) ); + } else { + $retry_after = $retry_after_header; + } - $retry_after += rand( 0, 5 ); // Add a random number of seconds to avoid all clients retrying at the same time. + $retry_after = max( 1, $retry_after ); + $retry_after = min( $max_wait, $retry_after ); + $retry_after += rand( 0, 5 ); - return $retry_after; + return (int) $retry_after; } /** diff --git a/src/tests/unit/RemoteTestRunnerPollTest.php b/src/tests/unit/RemoteTestRunnerPollTest.php new file mode 100644 index 000000000..9fdd600c8 --- /dev/null +++ b/src/tests/unit/RemoteTestRunnerPollTest.php @@ -0,0 +1,43 @@ +setAccessible( true ); + + return $ref->invoke( null, $failures, $poll_interval ); + } + + public function test_first_failure_backs_off_at_least_two_seconds(): void { + // The old behaviour was a flat sleep(1); the floor is now 2s (+ jitter). + $delay = $this->poll_retry_delay( 1, 15 ); + + $this->assertGreaterThanOrEqual( 2, $delay ); + } + + public function test_backoff_grows_with_consecutive_failures(): void { + // Base (pre-jitter) delay for failures 1..3 is 2, 4, 8 — so even with up to 5s of + // jitter the third failure cannot be quicker than the first's floor. + $this->assertGreaterThanOrEqual( 2, $this->poll_retry_delay( 1, 30 ) ); + $this->assertGreaterThanOrEqual( 4, $this->poll_retry_delay( 2, 30 ) ); + $this->assertGreaterThanOrEqual( 8, $this->poll_retry_delay( 3, 30 ) ); + } + + public function test_backoff_never_exceeds_poll_interval_plus_jitter(): void { + // Many failures cap the base delay at the poll interval; only jitter is added on top. + $poll_interval = 15; + for ( $failures = 1; $failures <= 10; $failures++ ) { + $delay = $this->poll_retry_delay( $failures, $poll_interval ); + $this->assertLessThanOrEqual( $poll_interval + 5, $delay ); + } + } +} diff --git a/src/tests/unit/RequestBuilderHttpStatusTest.php b/src/tests/unit/RequestBuilderHttpStatusTest.php index 4851506f3..5c17ab6c0 100644 --- a/src/tests/unit/RequestBuilderHttpStatusTest.php +++ b/src/tests/unit/RequestBuilderHttpStatusTest.php @@ -118,4 +118,31 @@ public function test_download_file_accepts_successful_mock_response(): void { $this->assertSame( 'zip bytes', file_get_contents( $path ) ); } + + public function test_download_file_429_fails_cleanly_without_html_snippet(): void { + $url = 'https://qit.woo.com/wp-content/uploads/qit-test-packages/uuid/package.zip?signature=secret'; + $path = $this->tmp_file_with( '' ); + unlink( $path ); + + App::setVar( 'mock_' . $url, [ + 'status' => 429, + 'body' => '429 Too Many Requests...', + ] ); + + try { + RequestBuilder::download_file( $url, $path ); + $this->fail( 'Expected a RuntimeException for a rate-limited download.' ); + } catch ( \RuntimeException $e ) { + $message = $e->getMessage(); + + // The user-facing message must be clean: no raw HTML, no signed-URL secrets. + $this->assertStringContainsString( '429', $message ); + $this->assertStringNotContainsString( 'assertStringNotContainsString( 'assertStringNotContainsString( 'signature=secret', $message ); + } + + // The partial error page must not be left on disk masquerading as a zip. + $this->assertFileNotExists( $path ); + } } diff --git a/src/tests/unit/RequestBuilderTest.php b/src/tests/unit/RequestBuilderTest.php index 0c98a74bd..3e762e6f3 100644 --- a/src/tests/unit/RequestBuilderTest.php +++ b/src/tests/unit/RequestBuilderTest.php @@ -3,6 +3,7 @@ namespace QIT_CLI_Tests; use PHPUnit\Framework\AssertionFailedError; +use QIT_CLI\App; use QIT_CLI\RequestBuilder; use PHPUnit\Framework\TestCase; @@ -18,6 +19,14 @@ protected function setUp(): void { public function wait_after_429( string $headers, int $max_wait = 60 ): int { return parent::wait_after_429( $headers, $max_wait ); } + + public function parse_retry_after_header_public( string $headers ): ?int { + return parent::parse_retry_after_header( $headers ); + } + + public function calculate_retry_delay_public( ?int $retry_after_header, int $attempt, int $max_wait = 180 ): int { + return parent::calculate_retry_delay( $retry_after_header, $attempt, $max_wait ); + } }; } @@ -78,6 +87,67 @@ public function test_exponential_backoff() { $this->assertRetryDelayWithinRange( 160, $this->sut->wait_after_429( $headers, 200 ), 5 ); } + public function test_parse_retry_after_numeric() { + $this->assertSame( 120, $this->sut->parse_retry_after_header_public( "Retry-After: 120\r\nOther: x" ) ); + } + + public function test_parse_retry_after_is_case_insensitive() { + // HTTP/2 lower-cases header names; we must still find it. + $this->assertSame( 30, $this->sut->parse_retry_after_header_public( "retry-after: 30\r\nOther: x" ) ); + $this->assertSame( 30, $this->sut->parse_retry_after_header_public( "RETRY-AFTER: 30\r\nOther: x" ) ); + } + + public function test_parse_retry_after_absent_returns_null() { + $this->assertNull( $this->sut->parse_retry_after_header_public( "Other-Header: value" ) ); + } + + public function test_parse_retry_after_invalid_returns_null() { + $this->assertNull( $this->sut->parse_retry_after_header_public( "Retry-After: not-a-date\r\nOther: x" ) ); + } + + public function test_parse_retry_after_past_date_clamps_to_zero() { + $past = ( new \DateTime( '-2 hours' ) )->format( \DateTimeInterface::RFC7231 ); + $headers = "Retry-After: $past\r\nOther: x"; + + $this->assertSame( 0, $this->sut->parse_retry_after_header_public( $headers ) ); + } + + public function test_calculate_retry_delay_honors_header_within_cap() { + // Header value is returned (plus 0-5s jitter) when under the cap. + $this->assertRetryDelayWithinRange( 90, $this->sut->calculate_retry_delay_public( 90, 0, 180 ), 5 ); + } + + public function test_calculate_retry_delay_caps_long_header() { + // A large header value is capped at max_wait (plus jitter). + $this->assertRetryDelayWithinRange( 180, $this->sut->calculate_retry_delay_public( 3600, 0, 180 ), 5 ); + } + + public function test_calculate_retry_delay_backoff_when_no_header() { + // 0-based attempts: 5, 10, 20, 40 ... + $this->assertRetryDelayWithinRange( 5, $this->sut->calculate_retry_delay_public( null, 0, 180 ), 5 ); + $this->assertRetryDelayWithinRange( 10, $this->sut->calculate_retry_delay_public( null, 1, 180 ), 5 ); + $this->assertRetryDelayWithinRange( 20, $this->sut->calculate_retry_delay_public( null, 2, 180 ), 5 ); + $this->assertRetryDelayWithinRange( 40, $this->sut->calculate_retry_delay_public( null, 3, 180 ), 5 ); + } + + public function test_retry_429_budget_resets_each_request() { + // A reused builder (e.g. Upload.php sends every chunk through one instance) must not + // carry an exhausted 429 budget into the next request. Simulate a prior request having + // burned the whole budget, then assert the next request() starts fresh. + $url = 'https://example.com/reset-budget-' . __FUNCTION__; + App::setVar( 'mock_' . $url, '{"ok":true}' ); + + $sut = new class( $url ) extends RequestBuilder { + public $retry_429 = 0; + }; + + $sut->request(); + + $this->assertSame( 5, $sut->retry_429 ); + + App::offsetUnset( 'mock_' . $url ); + } + // // Some tests for our custom assertion. //