From 5eddc262dea97b3c99f5188ba9577eb15c692a48 Mon Sep 17 00:00:00 2001 From: Richard McDaniel <1130888+rmcdaniel@users.noreply.github.com> Date: Thu, 29 Oct 2026 20:44:29 +0000 Subject: [PATCH] fix: measure complete update validation request across retries --- .github/workflows/server-parity.yml | 3 +- .../server-parity/update-validation-probe.php | 8 +- ...ServerParityUpdateValidationTimingTest.mjs | 94 +++++++++++++++++++ 3 files changed, 100 insertions(+), 5 deletions(-) create mode 100644 tests/Unit/ServerParityUpdateValidationTimingTest.mjs diff --git a/.github/workflows/server-parity.yml b/.github/workflows/server-parity.yml index f461a6396..7110f3c3d 100644 --- a/.github/workflows/server-parity.yml +++ b/.github/workflows/server-parity.yml @@ -92,6 +92,7 @@ on: - tests/Unit/ServerParityUpdateValidationContractTest.mjs - tests/Unit/ServerParityFixtureSelectionTest.mjs - tests/Unit/ServerParityUpdateValidationRetryTest.mjs + - tests/Unit/ServerParityUpdateValidationTimingTest.mjs - tests/Unit/ServerParityKilledAuthorPollTest.mjs - tests/Unit/ServerParityImagePullTest.mjs - tests/Unit/ServerParityAdapterCacheTest.mjs @@ -1991,7 +1992,7 @@ jobs: bash scripts/ci/run-composer.sh --rm -v "$PWD:/source" -w /source -- \ install --working-dir=scripts/conformance/server-parity --no-interaction --no-progress docker run --rm --user=1000:1000 --entrypoint node -v "$PWD:/source:ro" -w /source \ - "$image" --test tests/Unit/ServerParityRunnerTest.mjs tests/Unit/ServerParityRunnerBlockedExcerptTest.mjs tests/Unit/ServerParityProbeNotesTest.mjs tests/Unit/ServerParitySdkDirectionLanesTest.mjs tests/Unit/ServerParityCodecDeadlineCellsTest.mjs tests/Unit/ServerParityCooperativeContractTest.mjs tests/Unit/ServerParityChildCancellationContractTest.mjs tests/Unit/ServerParityScheduleContractTest.mjs tests/Unit/ServerParityVisibilityContractTest.mjs tests/Unit/ServerParityAdmissionContractTest.mjs tests/Unit/ServerParityRoleTokenContractTest.mjs tests/Unit/ServerParityWorkerDeregistrationContractTest.mjs tests/Unit/ServerParitySearchAttributeContractTest.mjs tests/Unit/ServerParityWorkerListingContractTest.mjs tests/Unit/ServerParityWorkerReplacementContractTest.mjs tests/Unit/ServerParityPatchDeploymentContractTest.mjs tests/Unit/ServerParityWaitingHistoryContractTest.mjs tests/Unit/ServerParityTaskRetryContractTest.mjs tests/Unit/ServerParityPublishedPatchContractTest.mjs tests/Unit/ServerParityPublishedPatchTransportTest.mjs tests/Unit/ServerParityRecordFileTest.mjs tests/Unit/ServerParityFailureLocationTest.mjs tests/Unit/ServerParityFailureExcerptTest.mjs tests/Unit/ServerParityLateWorkflowCompletionContractTest.mjs tests/Unit/ServerParityStorageTestContractTest.mjs tests/Unit/ServerParitySchedulePoliciesContractTest.mjs tests/Unit/ServerParitySignalsBeforeWorkerContractTest.mjs tests/Unit/ServerParityScheduleCatalogContractTest.mjs tests/Unit/ServerParityOperatorMetricsContractTest.mjs tests/Unit/ServerParityActivityLeaseRenewalContractTest.mjs tests/Unit/ServerParityConcurrentWaitsContractTest.mjs tests/Unit/ServerParityContinueTransfersContractTest.mjs tests/Unit/ServerParityChildDescriptionsContractTest.mjs tests/Unit/ServerParityWorkerErrorBodiesContractTest.mjs tests/Unit/ServerParityLargeCommandBatchesContractTest.mjs tests/Unit/ServerParityManyUpdatesContractTest.mjs tests/Unit/ServerParityStartSearchAttributesContractTest.mjs tests/Unit/ServerParityQueryArgumentsContractTest.mjs tests/Unit/ServerParityQueryContractArgumentsContractTest.mjs tests/Unit/ServerParityParentCloseCancellationContractTest.mjs tests/Unit/ServerParityRecordLocalActivityContractTest.mjs tests/Unit/ServerParityActivityCancellationAckContractTest.mjs tests/Unit/ServerParityServiceCatalogContractTest.mjs tests/Unit/ServerParityServiceEndpointsContractTest.mjs tests/Unit/ServerParityServiceCallsContractTest.mjs tests/Unit/ServerParityWorkflowImportContractTest.mjs tests/Unit/ServerParityWaterlineImportContractTest.mjs tests/Unit/ServerParitySystemMetricsContractTest.mjs tests/Unit/ServerParityOperatorDashboardTypesContractTest.mjs tests/Unit/ServerParityPrometheusMetricsContractTest.mjs tests/Unit/ServerParityPayloadCleanupContractTest.mjs tests/Unit/ServerParityRepairPassContractTest.mjs tests/Unit/ServerParityClusterInfoContractTest.mjs tests/Unit/ServerParityNamespaceDeleteContractTest.mjs tests/Unit/ServerParityMessageStreamsContractTest.mjs tests/Unit/ServerParityCancellationScopesContractTest.mjs tests/Unit/ServerParityWorkflowPollRequestContractTest.mjs tests/Unit/ServerParityUpdateValidationContractTest.mjs tests/Unit/ServerParityFixtureSelectionTest.mjs tests/Unit/ServerParityUpdateValidationRetryTest.mjs tests/Unit/ServerParityKilledAuthorPollTest.mjs tests/Unit/ServerParityImagePullTest.mjs tests/Unit/ServerParityAdapterCacheTest.mjs tests/Unit/ServerParityWorkerSessionsContractTest.mjs tests/Unit/ServerParityWorkerSessionActivitiesContractTest.mjs tests/Unit/ServerParityNexusOperationsContractTest.mjs tests/Unit/ServerParityBridgeAdaptersContractTest.mjs tests/Unit/ServerParityWorkflowStreamWritesContractTest.mjs > parity-evidence/comparator-tests.txt + "$image" --test tests/Unit/ServerParityRunnerTest.mjs tests/Unit/ServerParityRunnerBlockedExcerptTest.mjs tests/Unit/ServerParityProbeNotesTest.mjs tests/Unit/ServerParitySdkDirectionLanesTest.mjs tests/Unit/ServerParityCodecDeadlineCellsTest.mjs tests/Unit/ServerParityCooperativeContractTest.mjs tests/Unit/ServerParityChildCancellationContractTest.mjs tests/Unit/ServerParityScheduleContractTest.mjs tests/Unit/ServerParityVisibilityContractTest.mjs tests/Unit/ServerParityAdmissionContractTest.mjs tests/Unit/ServerParityRoleTokenContractTest.mjs tests/Unit/ServerParityWorkerDeregistrationContractTest.mjs tests/Unit/ServerParitySearchAttributeContractTest.mjs tests/Unit/ServerParityWorkerListingContractTest.mjs tests/Unit/ServerParityWorkerReplacementContractTest.mjs tests/Unit/ServerParityPatchDeploymentContractTest.mjs tests/Unit/ServerParityWaitingHistoryContractTest.mjs tests/Unit/ServerParityTaskRetryContractTest.mjs tests/Unit/ServerParityPublishedPatchContractTest.mjs tests/Unit/ServerParityPublishedPatchTransportTest.mjs tests/Unit/ServerParityRecordFileTest.mjs tests/Unit/ServerParityFailureLocationTest.mjs tests/Unit/ServerParityFailureExcerptTest.mjs tests/Unit/ServerParityLateWorkflowCompletionContractTest.mjs tests/Unit/ServerParityStorageTestContractTest.mjs tests/Unit/ServerParitySchedulePoliciesContractTest.mjs tests/Unit/ServerParitySignalsBeforeWorkerContractTest.mjs tests/Unit/ServerParityScheduleCatalogContractTest.mjs tests/Unit/ServerParityOperatorMetricsContractTest.mjs tests/Unit/ServerParityActivityLeaseRenewalContractTest.mjs tests/Unit/ServerParityConcurrentWaitsContractTest.mjs tests/Unit/ServerParityContinueTransfersContractTest.mjs tests/Unit/ServerParityChildDescriptionsContractTest.mjs tests/Unit/ServerParityWorkerErrorBodiesContractTest.mjs tests/Unit/ServerParityLargeCommandBatchesContractTest.mjs tests/Unit/ServerParityManyUpdatesContractTest.mjs tests/Unit/ServerParityStartSearchAttributesContractTest.mjs tests/Unit/ServerParityQueryArgumentsContractTest.mjs tests/Unit/ServerParityQueryContractArgumentsContractTest.mjs tests/Unit/ServerParityParentCloseCancellationContractTest.mjs tests/Unit/ServerParityRecordLocalActivityContractTest.mjs tests/Unit/ServerParityActivityCancellationAckContractTest.mjs tests/Unit/ServerParityServiceCatalogContractTest.mjs tests/Unit/ServerParityServiceEndpointsContractTest.mjs tests/Unit/ServerParityServiceCallsContractTest.mjs tests/Unit/ServerParityWorkflowImportContractTest.mjs tests/Unit/ServerParityWaterlineImportContractTest.mjs tests/Unit/ServerParitySystemMetricsContractTest.mjs tests/Unit/ServerParityOperatorDashboardTypesContractTest.mjs tests/Unit/ServerParityPrometheusMetricsContractTest.mjs tests/Unit/ServerParityPayloadCleanupContractTest.mjs tests/Unit/ServerParityRepairPassContractTest.mjs tests/Unit/ServerParityClusterInfoContractTest.mjs tests/Unit/ServerParityNamespaceDeleteContractTest.mjs tests/Unit/ServerParityMessageStreamsContractTest.mjs tests/Unit/ServerParityCancellationScopesContractTest.mjs tests/Unit/ServerParityWorkflowPollRequestContractTest.mjs tests/Unit/ServerParityUpdateValidationContractTest.mjs tests/Unit/ServerParityFixtureSelectionTest.mjs tests/Unit/ServerParityUpdateValidationRetryTest.mjs tests/Unit/ServerParityUpdateValidationTimingTest.mjs tests/Unit/ServerParityKilledAuthorPollTest.mjs tests/Unit/ServerParityImagePullTest.mjs tests/Unit/ServerParityAdapterCacheTest.mjs tests/Unit/ServerParityWorkerSessionsContractTest.mjs tests/Unit/ServerParityWorkerSessionActivitiesContractTest.mjs tests/Unit/ServerParityNexusOperationsContractTest.mjs tests/Unit/ServerParityBridgeAdaptersContractTest.mjs tests/Unit/ServerParityWorkflowStreamWritesContractTest.mjs > parity-evidence/comparator-tests.txt docker run --rm --user=1000:1000 --cpus=1 --memory=256m --memory-swap=256m \ --network=none --entrypoint node -v "$PWD:/source:ro" -w /source \ "$image" --test tests/Unit/ServerParityCodecDeadlineLoadTest.mjs > parity-evidence/codec-load-tests.txt diff --git a/scripts/conformance/server-parity/update-validation-probe.php b/scripts/conformance/server-parity/update-validation-probe.php index 222feecbe..84a7ec0be 100644 --- a/scripts/conformance/server-parity/update-validation-probe.php +++ b/scripts/conformance/server-parity/update-validation-probe.php @@ -39,8 +39,8 @@ function finishHttpUpdateValidation(Client $client, array $fixture, string $work // A request that waits for a validator, sent from a child process. Like // the requests above, it retries only the documented lock-pressure // refusal, which committed nothing (lockPressureOperationRetryDelay); - // `seconds` is the answered attempt's own wait, and retries are reported - // on stderr. + // `seconds` includes the whole logical request: every attempt and its + // backoff. Retries are also reported on stderr. $background = static function (string $workflow, string $update, array $body) use ($url, $token): array { $child = <<<'PHP' [, $url, $token, $path, $body, $retryRule] = $argv; @@ -51,8 +51,8 @@ function finishHttpUpdateValidation(Client $client, array $fixture, string $work 'ignore_errors' => true, 'timeout' => 60]]); $retries = []; $waited = 0.0; +$started = hrtime(true); while (true) { - $started = microtime(true); $response = file_get_contents(rtrim($url, '/').'/api/'.$path, false, $context); preg_match('#^HTTP/\S+ (\d{3})#', $http_response_header[0] ?? '', $status); $status = (int) ($status[1] ?? 0); @@ -68,7 +68,7 @@ function finishHttpUpdateValidation(Client $client, array $fixture, string $work if ($retries !== []) { fwrite(STDERR, json_encode(['lock_pressure_update_retries' => ['path' => $path, 'delays' => $retries]]).PHP_EOL); } -echo json_encode(['status' => $status, 'response' => $decoded, 'seconds' => microtime(true) - $started]); +echo json_encode(['status' => $status, 'response' => $decoded, 'seconds' => (hrtime(true) - $started) / 1_000_000_000]); PHP; $process = proc_open([PHP_BINARY, '-r', $child, '--', $url, $token ?? '', "workflows/{$workflow}/update/{$update}", json_encode($body, JSON_THROW_ON_ERROR), __DIR__.'/lock-pressure-retry.php'], diff --git a/tests/Unit/ServerParityUpdateValidationTimingTest.mjs b/tests/Unit/ServerParityUpdateValidationTimingTest.mjs new file mode 100644 index 000000000..659641f7b --- /dev/null +++ b/tests/Unit/ServerParityUpdateValidationTimingTest.mjs @@ -0,0 +1,94 @@ +import test from 'node:test'; +import assert from 'node:assert/strict'; +import http from 'node:http'; +import {spawn} from 'node:child_process'; +import {once} from 'node:events'; +import {readFileSync} from 'node:fs'; +import {fileURLToPath} from 'node:url'; + +// Run the actual background request program, with its real retry policy, +// against HTTP responses. No SDK, worker or frozen timing bounds are replaced. +const source = readFileSync(new URL('../../scripts/conformance/server-parity/update-validation-probe.php', import.meta.url), 'utf8'); +const childProgram = source.match(/\$child = <<<'PHP'\n([\s\S]*?)\nPHP;/)?.[1]; +const retryRule = fileURLToPath(new URL('../../scripts/conformance/server-parity/lock-pressure-retry.php', import.meta.url)); +const path = 'workflows/timing-workflow/update/approve'; +const body = '{"value":{"original":true},"idempotency_key":"same-request"}'; +const pressure = {reason: 'backend_lock_pressure', retryable: true, retry_after_seconds: 0.1}; +const cached = {accepted: false, reason: 'deduped_existing_command', run_id: 'original-run', command_id: 'original-command'}; + +async function request(t, replies) { + assert(childProgram, 'background request program must be present'); + const received = []; + const timers = new Set(); + const server = http.createServer((incoming, response) => { + const chunks = []; + incoming.on('data', bytes => chunks.push(bytes)); + incoming.on('end', () => { + received.push({method: incoming.method, path: incoming.url, body: Buffer.concat(chunks).toString()}); + const reply = replies[received.length - 1] ?? {status: 500, body: {unexpected_request: true}}; + const timer = setTimeout(() => { + timers.delete(timer); + response.writeHead(reply.status, {'content-type': 'application/json'}); + response.end(JSON.stringify(reply.body)); + }, reply.delay ?? 0); + timers.add(timer); + }); + }); + let child; + let closed; + t.after(async () => { + if (child && child.exitCode === null && child.signalCode === null) child.kill(); + if (closed) await closed; + for (const timer of timers) clearTimeout(timer); + server.closeAllConnections(); + await new Promise(resolve => server.close(resolve)); + }); + server.listen(0, '127.0.0.1'); + await once(server, 'listening'); + child = spawn('php', ['-r', childProgram, '--', `http://127.0.0.1:${server.address().port}`, '', path, body, retryRule], + {stdio: ['ignore', 'pipe', 'pipe']}); + closed = once(child, 'close'); + let stdout = '', stderr = ''; + child.stdout.on('data', bytes => {stdout += bytes;}); + child.stderr.on('data', bytes => {stderr += bytes;}); + const [code, signal] = await closed; + assert.equal(code, 0, stderr); + assert.equal(signal, null); + assert.deepEqual(received, replies.map(() => ({method: 'POST', path: '/api/' + path, body}))); + return {...JSON.parse(stdout), stderr}; +} + +test('elapsed time includes the refused attempt and backoff before an accepted update', {timeout: 5000}, async t => { + const accepted = {accepted: true, run_id: 'original-run', command_id: 'original-command'}; + const result = await request(t, [{status: 503, body: pressure, delay: 60}, {status: 202, body: accepted}]); + assert.equal(result.status, 202); + assert.deepEqual(result.response, accepted); + assert(result.seconds >= 0.15, `whole request took ${result.seconds}s`); + assert.deepEqual(JSON.parse(result.stderr), {lock_pressure_update_retries: {path, delays: [0.1]}}); +}); + +test('elapsed time includes every refused attempt and backoff before the original cached receipt', {timeout: 5000}, async t => { + const result = await request(t, [{status: 503, body: pressure, delay: 40}, + {status: 503, body: pressure, delay: 40}, {status: 200, body: cached}]); + assert.equal(result.status, 200); + assert.deepEqual(result.response, cached); + assert(result.seconds >= 0.27, `whole request took ${result.seconds}s`); + assert.deepEqual(JSON.parse(result.stderr), {lock_pressure_update_retries: {path, delays: [0.1, 0.1]}}); +}); + +test('an immediate cached receipt keeps its original response without retry', {timeout: 5000}, async t => { + const result = await request(t, [{status: 200, body: cached}]); + assert.equal(result.status, 200); + assert.deepEqual(result.response, cached); + assert(result.seconds >= 0); + assert.equal(result.stderr, ''); +}); + +test('an unrelated server failure keeps its original response without retry', {timeout: 5000}, async t => { + const failure = {reason: 'unrelated_failure', retryable: true}; + const result = await request(t, [{status: 500, body: failure}]); + assert.equal(result.status, 500); + assert.deepEqual(result.response, failure); + assert(result.seconds >= 0); + assert.equal(result.stderr, ''); +});