Fix update-validation probe timing across retries

.github/workflows/server-parity.yml

@@ -94,6 +94,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
@@ -1996,7 +1997,78 @@ 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/ServerParityChildRetriesContractTest.mjs tests/Unit/ServerParityChildVisibilityContractTest.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/ServerParityChildRetriesContractTest.mjs \
+              tests/Unit/ServerParityChildVisibilityContractTest.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

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'],

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, '');
+});