Server parity: legacy-marker 503 recovery check fails intermittently on published PHP (SQLite) #754

Activity

1. rmcdaniel commented on Oct 25, 2026

   

   rmcdaniel

   on Oct 25, 2026

   MemberAuthor

   More actions

   Two more single-job flakes in the following cycles (on #752), each passing on a rerun of only that job:

   1. mysql-execution (mariadb-10.11, sdk-directions), run 40148128623 attempt 1: sdk-queries recorded query-sdk-python-rust with HTTP status 0 instead of 200 against native. That's a transport failure, not a different answer. The same profile passed on the other five databases in that run.
   2. postgres-storage (postgres-17, cohorts), run 40151134683 attempt 1: corrected cohort python-clock-genuine-one failed with false !== true after the PHP record passed.

   Like the legacy-marker case, both are timing-sensitive steps under concurrent load, and the retained artifacts lack the failing request detail. The first next action here (a bounded failing-case excerpt in the artifact summary) would make all three diagnosable.
2. rmcdaniel commented on Oct 25, 2026

   

   rmcdaniel

   on Oct 25, 2026

   MemberAuthor

   More actions

   Third flake recurrence, and the first repeat of one exact case:

   • mysql-execution (mysql-8.0, sdk-directions), run 40156433545 attempt 1 (job 121059713069, Rust #325: activity cancellation acknowledgement like Server 2.11.1 #745 head 6df4e73). sdk-queries again recorded query-sdk-python-rust against native with HTTP status 0 instead of 200. The embedded and PHP recordings of the same case passed in that job, as did the other eight SDK profiles.

   It's the same case as run 40148128623 (mariadb-10.11, on #752 head 5287ee9, which changes no Rust source). Two occurrences, both on MySQL-family databases, both with the Python workflow worker and the Rust client, so this is a pattern and not random noise.

   In published-sdk-patch/observe-http.mjs, status 0 means no upstream status arrived: either the client closed the request first (client_cancelled) or the upstream connection errored (transport_error). The retained artifact again has no journal for that request, so we can't yet tell which one happened or which request it was (query call, query-task poll, or completion).

   Next action is unchanged but now has a concrete first target: keep a bounded excerpt of the failing case's observer journal (method, path, status, client_cancelled, transport_error, timing) in the artifact summary. Then check the Rust client's query HTTP timeout against native's query-task round trip under three-lane load.
3. rmcdaniel

   added 3 commits that reference this issue on Oct 25, 2026

   Name the request and transport flags when an SDK query status is wrong

   ...

   4ff1f2c

   Release an SDK query author only after its completion response

   ...

   c79a08e

   Release an SDK query author only after its completion response

   ...

   87b52c8
4. rmcdaniel commented on Oct 25, 2026

   

   rmcdaniel

   on Oct 25, 2026

   MemberAuthor

   More actions

   Root cause of the query-sdk-python-rust status-0 flake: the test harness, not the server.

   Mechanism, from reading the source:

   1. Native's finish_query commits the completion and then wakes the waiting query caller (tx.commit() then wake.notify_waiters() in rust/src/runtime/queries.rs). The completion's own HTTP response is sent after that, so the caller's answer and the author's completion response race. That order is correct: the completion is durable before anyone can see it.
   2. In sdk-query-direction-probe.php, the author's stop trigger (its receipt file) was written as soon as the query client finished.
   3. Published Python SDK 2.5.4 runs query tasks on a dedicated poller thread when the client can be cloned. It completes them inline (_poll_query_tasks(track_tasks=False) then await client.complete_query_task). Worker.stop() cancels that thread's task (_request_query_task_thread_stop calls task.cancel()).
   4. With the Rust client, which starts and exits quickly, the chain "caller answered → probe writes the trigger → Python author stops" can beat the author's completion response. The in-flight completion is cancelled, and the observer records it as client_cancelled with status 0. Native had already applied the completion, which is why the client got the right answer.

   This explains why only the Python author is affected (PHP and Rust authors don't cancel an in-flight completion on stop) and why the Rust client is the one that wins the race. Both hits were on MySQL-family databases, which is consistent with a longer commit window, but two samples don't prove that part.

   Fix (on branch rust-325-wip/ci-corrected-part, for the next CI PR):

   • 87b52c8: the probe now waits, within the existing fixture deadline, until the author's journal shows its own successful, uncancelled completion of the query task it claimed. Only then does it write the stop trigger. PHPUnit ServerParitySdkQueryTransportTest covers release-on-receipt and non-release for status 0, client_cancelled, transport_error, an empty response object, foreign receipts, wrong order, and foreign workflow or run.
   • 4ff1f2c: if a status is still wrong, the contract names the phase, method, path and the observer's transport flags (client_cancelled, transport_error, request_body_complete, upstream_request_started), never payload bytes. Two new node tests; both fail against the previous contract.

   This can't be reproduced deterministically in a unit test. It will be accepted when the sdk-directions lane stays green across cycles once this ships.
5. rmcdaniel

   added a commit that references this issue on Oct 25, 2026

   Print the contract line that refused a fixture

   ...

   7246971
6. rmcdaniel commented on Oct 25, 2026

   

   rmcdaniel

   on Oct 25, 2026

   MemberAuthor

   More actions

   Second occurrence of the legacy-marker check same original poll recovers (legacy-marker-contract.mjs:285), again on SQLite and again in the published PHP 2.11.1 record:

   • Run 40159712308, job execution-and-codec (corpus) 121069436918, Rust #325: fence held polls against replaced worker registrations (#734) #739 head 9b085b699. The case is legacy-one-marker-control (the first occurrence was legacy-two-markers-pending).
   • legacy-marker-profile.sh records php before rust and stops at the first failure. No rust record ran, so the failing record is published PHP, not native.
   • The PHP maintenance loop logged SQLSTATE[HY000]: General error: 5 database is locked three times at 04:08:11, about 30 s before the case. The retained access-log tail (64 KiB) starts after the failing phase, so no 503 is visible in it.

   This matches the open hypothesis: a 503 under SQLite lock pressure, then the phase reached its checkpoint while the worker waited out Retry-After, so the byte-identical retry was never sent. It's still unconfirmed for the same reason: the failing phase's request order isn't retained. The contract-line output in the queued CI PR (72469710a) will name the check but not the order. The next action remains a bounded failing-phase excerpt, or a contract branch for a worker that withdraws without retrying.
7. rmcdaniel

   added 2 commits that reference this issue on Oct 25, 2026

   Keep a value-free outline of every failed fixture's requests

   ...

   67d6dc4

   Merge pull request #756 from durable-workflow/rust-325-ci-corrected-part

   ...

   ac28bdb
8. rmcdaniel commented on Oct 25, 2026

   

   rmcdaniel

   on Oct 25, 2026

   MemberAuthor

   More actions

   Two new single-job flakes on #757 (run 40169120328 attempt 1, head a0ba83a95), both in PHP reference records. The contract-line output from #756 located each one straight from the job log:

   1. execution-and-codec (corpus), job 121097162204. Published PHP 2.11.1, the first record on SQLite: cooperative-pending-timer-cleanup: pre-request renewal belongs to original wait claim (cooperative-contract.mjs:7). The heartbeat path named a different workflow task id than the original wait claim, consistent with PHP's maintenance repair pass recreating the task under SQLite contention while the probe held its claim.
   2. mysql-execution (mysql-8.0, sdk-directions), job 121097162315. Embedded record of signal-selected-run-sdk-rust-php: 1 !== 0 at sdk-selected-run-signal-contract.mjs:207, which is task.repair_count === 0. The embedded application's repair pass repaired one task during the profile.

   Neither record is native, and #757 changes neither profile's steps. Both point at the same class: PHP's repair pass acting during a fixture phase that assumes no repair. Next, using the per-case request outline #756 added: check whether the fixtures should pause the reference maintenance loop around those phases (as published-sdk-patch/maintenance.sh already does on SQLite, Server #721), or accept a repaired task where the contract does not depend on it. Attempt 2 reruns only the failed jobs.
9. rmcdaniel

   added a commit that references this issue on Oct 25, 2026

   List stored workflow tasks in a failed case's excerpt

   ...

   2ad76ec
10. rmcdaniel commented on Oct 25, 2026

    

    rmcdaniel

    on Oct 25, 2026

    Last edited by rmcdaniel

    MemberAuthor

    More actions

    New single-job flake class, on #740 (run 40178942441, head 50f87f6ad, job execution-and-codec (corpus) 121126702494).

    update-validation-sqlite.sh records the update-validation fixture separately on SQLite, in this order: published PHP 2.11.1 (with its maintenance loop paused), embedded, Rust. It stops at the first failure. The failing record was the first one, published PHP:

    update-validation: update validation worker_lost waited for the validation timeout (0.06631088256835938 seconds)
      at scripts/conformance/server-parity/update-validation-contract.mjs:55
    

    The worker_lost step must wait out the validation timeout (VALIDATION_SECONDS) before PHP answers that the validating worker was lost. Here it answered after 0.066 s. The access-log tail shows the profile's other steps (uv-slow approve/reject) completing normally between 09:18:11 and 09:18:21. The branch's own changes don't touch update validation, and the published image doesn't run branch code. In the same run's main corpus, the PHP, embedded and Rust records of every corpus case had all passed.

    Hypothesis: the published PHP answered worker_lost early because its worker-liveness check saw the profile's worker as stale. That could happen if the probe's worker registration or heartbeat landed outside the staleness window under SQLite contention. The maintenance loop was paused for this record, so the repair pass is not a suspect. Unconfirmed. The retained artifact doesn't include the per-step timing of the update-validation record. Next: if it recurs, check the failing record's worker_lost request timing in the excerpt, now that #756's outline is on main.
11. rmcdaniel commented on Oct 25, 2026

    

    rmcdaniel

    on Oct 25, 2026

    MemberAuthor

    More actions

    Second update-validation occurrence on SQLite, now with a root cause. It's again the published PHP 2.11.1 reference record.

    Where. Run 40186725548, job execution-and-codec (corpus) 121150146353, on #759 head dc1872d31. #759 changes only CI wrapper code; nothing in the corpus part or update validation. The artifact's update-validation-php.failure-excerpt.txt names the record: update-validation (product-fail): update validation lost_approve. Every record of the main corpus (PHP, embedded, Rust) passed in the same job.

    What happened, from the retained PHP access and error logs:

    1. The probe started three background updates (uv-idle, uv-lost, uv-busy), then polled for the uv-lost worker's validation task.
    2. That poll (received 11:12:54) answered 503. PHP logged at the same moment:
       SQLSTATE[HY000]: General error: 5 database is locked (… SQL: update "workflow_update_validation_tasks" set "status" = leased, "attempt_count" = 1, "lease_owner" = parity-v1-update-validation-uv-lost, … "updated_at" = 2026-10-25 11:12:54.901954 …)
    3. With no task, the probe's lost_approve step sent POST /api/worker/update-validation-tasks/missing/approve and got 404 update_validation_task_not_found instead of 409 update_validator_worker_lost.

    Why. The PHP reference container runs with DB_SQLITE_BUSY_TIMEOUT=30000, yet the lease update failed in the same second the poll arrived, so a busy timeout didn't run out. Published 2.11.1's WorkflowUpdateValidationTaskBroker::claim() runs SELECT … lockForUpdate() and then the lease UPDATE in one DB::transaction. SQLite ignores FOR UPDATE, so the transaction holds a read snapshot when it tries to write. If another connection committed in between, SQLite refuses the read-to-write upgrade at once with SQLITE_BUSY, without calling the busy handler. The probe's three concurrent updates supply that other writer, even with the maintenance loop paused.

    Status on current code. Main's claim() runs the same transaction under WorkerProtocolMutationRetrier, so current PHP retries this lost write. Native takes SQLite's writer lock before its first read (BEGIN IMMEDIATE in begin()), so it can't hit the upgrade. Only the immutable published 2.11.1 reference has the defect.

    The first update-validation occurrence (comment 6395998224, worker_lost answering after 0.066 s) likely has the same cause: a lost lease or timeout write under the same contention. The legacy-marker and cooperative occurrences above all coincide with database is locked in the PHP logs too.

    Proposed next action (a separate CI PR after #759): when a published PHP reference record fails on SQLite and the PHP server logged database is locked during that record, rerun that one PHP record once against a fresh PHP database. Native and embedded records are never retried, and a failure without the lock error still fails at once. This removes a full fixtures rerun (about 25 min) per occurrence without loosening any comparison.
12. rmcdaniel commented on Oct 25, 2026

    

    rmcdaniel

    on Oct 25, 2026

    MemberAuthor

    More actions

    Second occurrence of the corrected-cohort python-clock-genuine-one flake (false !== true after the PHP portable record passed; the first was run 40151134683). This time #756's failure excerpt locates it.

    • Where: run 40206210357, job mysql-execution (existing-php-mysql-matrix, corrected-markers) 121209004705, on CI: pull each fixture job's pinned images with bounded retries first #762 head 1575b00a9. CI: pull each fixture job's pinned images with bounded retries first #762 only adds image pulls before each job's first container.
    • Which record: corrected-marker/php/clock-record.failure-excerpt.txt, the published PHP 2.11.1 reference clock record. No native record was involved.
    • Which assertion: corrected-clock-contract.mjs:100. Every client-cancelled poll must show request_body_complete=true and upstream_request_started=true.
    • Which request: requests[34] POST /api/worker/activity-tasks/poll 0 client_cancelled=true, with neither flag set. The six other cancelled polls in the record ([32] [33] [62] [63] [93] [94]) all show both flags. [34] is in the window where the profile stops the original Python worker with SIGKILL (exit -9), whose polls the contract expects to be cancelled.

    Reading: the killed original worker's activity poll was cancelled before the observing proxy had forwarded it upstream, so the PHP server never received that request. Nothing about the server's behavior differs. The contract assumes every cancelled poll reached upstream, which a SIGKILL landing mid-send can violate under load. This is a fixture-contract timing defect, not a reference or native product defect.

    Next action: narrow the contract. A client-cancelled poll from the killed original actor may show upstream_request_started=false, meaning the server never saw it. Every request the server did receive keeps today's checks, and so does every cancelled poll from a live actor. Proxy semantics to confirm first: whether request_body_complete can be false while the recorded body parses.