From 44ea7e44430cdb023361e60421f65fdee4bacc31 Mon Sep 17 00:00:00 2001 From: makseq Date: Tue, 11 Aug 2026 22:24:51 +0300 Subject: [PATCH] =?UTF-8?q?Notice=20the=20stop=20=E2=80=94=20in=20every=20?= =?UTF-8?q?wait,=20not=20just=20the=20one=20that=20was=20measured?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The claim this started from was that `node.py` does not handle a stop. It does, and has since the rewrite: a handler on SIGTERM and SIGINT that sets a flag and nothing more, the flag checked between units of work, the inventory at module scope, a marker written last with `status: "cancelled"` and `exit_code: 20` agreeing with the code the process returns. Every line of the shape `docs/AUTHORING.md` prescribes was there. The gaps were elsewhere. THE MECHANISM THAT MADE THE FLAG READABLE DID NOTHING A flag cannot be read by a process parked in a socket call, and this file knew that — it kept a ledger of transfers in flight and its handler closed them. Neither half worked, and both were measured rather than argued: * it put the RESPONSE on the ledger, and a response exists only once the store has begun to answer, so during the wait that matters the ledger is empty; * it called close(), which does not interrupt a read that is already blocked. Mid-body that raises `RuntimeError: reentrant call inside <_io.BufferedReader>` INSIDE the handler, where contextlib.suppress swallows it, and the read then waits out its whole timeout regardless. Stop latency was therefore the socket timeout: 12.2s during a held-open download, 10.2s during an upload, 25.2s against a store that never answers — out of a nominal thirty that PROTOCOL.md is explicit nobody is promised. The connection now goes on the ledger before a byte is sent, and the handler calls shutdown(SHUT_RDWR). Measured after: 0.22s and 0.24s. AND THEN THE SAME DEFECT, TWICE MORE, IN THE SAME FILE Review found the fix reproduced its own defect one layer up. "Not on the ledger during the wait that matters" had been fixed for the wait that had been measured; there are four waits on this path and they are reached through different objects. * GETTING A CONNECTION — DNS, the TCP connect and the TLS handshake — was governed by the 25-second transfer timeout, and cannot be interrupted at all: `ssl` detaches the plain socket while wrapping it, so shutting that down raises `Bad file descriptor` and the handshake runs to the timeout anyway (measured). What cannot be interrupted has to be bounded, so it now has its own three-second budget, and the flag is re-checked the instant the call returns so a stop that arrived during it does not go on to start a request. Measured: 25.2s -> 3.2s. * READING THE BODY had an empty ledger, because `http.client` closes the connection as soon as it has parsed the headers of a `Connection: close` response — which urllib sets on every request — and the `close()` override took the entry off. The override is gone; one request is in flight at a time, so the next connection simply replaces the entry. Measured: 24.7s -> 0.3s. The TLS half also closed a hole in what the suite can see: production is https only and this harness's store is plain http, so the mechanism had been proved against the wrong protocol. It needed no certificate authority and no `openssl` — a handshake stalls before any certificate is offered, so a listener that accepts and says nothing is enough. `conformance/stalling.py` is that listener, and it is also what produces the mid-body case, which the store's hooks cannot: they fire while a request is still being authorised, before a byte of the response exists. THE EXCEPTION FOR A SECOND STOP WAS SWALLOWING THE FIRST "Nothing may abandon the receipt" was applied to every marker, including one claiming success. A stop landing while THAT was in flight changed nothing: flag set, upload left alone, upload lands, and the step returns 0 — a document saying `succeeded` inside a launch the orchestrator records as cancelled, which is what `_step_account` renders for a human. Deterministic, and measured: exit 0, receipts written ['succeeded']. The protection is now asymmetric, which is the argument that was made for it in the first place. A receipt reporting a failure or a stop cannot be made worse by being cut short and is the run's only account: protected. A receipt claiming success is the one document a stop can turn into a lie: not protected — the handler cuts it and the run writes the cancellation it has become, with the same inventory, so salvage publishes exactly as much as a success would have. The flag is checked once more after that write, before 0 is returned. THE HARNESS NEVER ASKED FOR THE RECEIPT Four cancellation tests, and not one required a marker to exist. Measured, not supposed: a copy of node.py that writes no marker on the stop path still passes three of the four. Seven tests now close all of it, all conforms_today and all basis_reference_quality: * a stopped step leaves a receipt, and it says `cancelled`; * the receipt carries the code the process really returned, and it is 20; * the receipt claims no object the store never received; * a stop is noticed without waiting for the transfer it landed in; * a stop mid-body does not wait for the rest of the body; * a stop during a TLS handshake is bounded even though it cannot be cut; * a stop during the success receipt is not reported as a success. None may carry basis_contract. external/contract.py does say "A cancelled run still writes a marker", but it says it while explaining what a field means, and everything the platform DOES with an absent marker here treats it as ordinary: _salvage_what_the_step_produced publishes "what a FAILED or cancelled step managed to write" and returns nothing when there is none, and collection reports "No completion marker was written…" as a finding rather than a refusal. A marker is required only after a reported success. Exit 20 is the same shape: _classify answers 'cancelled' whether or not the step said so — read the other way round, 20 is the only signal that says "stopped" rather than "broken" when the platform was not the party that asked. MUTATION EVIDENCE * handler never installed -> receipt test: "its receipt says 'succeeded'"; promptness test: 25.2s * shutdown() put back to close() -> promptness test only: 25.2s, exit 20 * marker claims outputs/ghost.csv -> over-claim test names the ghost * no marker on the stop path -> receipt test; the other two SKIP, naming the legal ending * connect budget removed -> TLS test: 25.2s * close() override restored -> mid-body test: 24.7s * one elapsed deadline replaced by the stdlib's per-address spend, same number -> multi-address test: 30.6s * the name lookup left unbounded -> lookup test: 40.6s * the check between the receipt landing and exit 0 removed -> receipt test: "asked to stop and exited 0" * the listener announcing on accept() instead of on evidence -> harness self-test: "announced a stall before the client had said anything" * the receipt corrected by a second document (round three's design) -> "the step wrote 2 completion markers for one run" * the receipt's elapsed deadline removed -> "spent 39.7s on a receipt whose answer was dribbled out over forty" * the connect deadline not recomputed after a proxy's CONNECT -> "spent 17.6s getting a connection through a proxy that took seven of them to answer" A RETRACTION, AND THE SAME LESSON A THIRD TIME Review of the above found two things wrong with it, and the first is a design this commit withdraws rather than defends. ASYMMETRIC PROTECTION IS WRONG. Leaving a success receipt abandonable does not prevent the lie it was aimed at; it makes which document survives unknowable. Once the store has the whole body it may commit it, and cutting the socket revokes nothing — so the cancellation written next is a second write to the same key that can OVERLAP the first, and nothing defines which of two overlapping writes wins, in this step or in any object store. The harness shows it directly: its delay hook holds the first commit back, the cancellation lands first, and the receipt the store serves says `succeeded` with the process exiting 20 beside it. The test written for that design looked away from the value the store serves and blamed the harness for it, which is the tell — a test that must avert its eyes is reporting a design problem. So the receipt is protected whatever it says, the check happens AFTER that write, and the correction begins only once the first has finished. The writes are sequential, the survivor is knowable, and the test asserts it. The defence is now observable too: the mutation that removes the check was GREEN before, because abandonment covered for it, and is red now. THE "BOUNDED" WAIT WAS NOT BOUNDED. Three seconds was not an elapsed deadline and could not have been: `socket.create_connection` resolves the name before there is a socket to time, then applies the number separately to each address. Measured in a container: one silently-dropped address with timeout=4 takes 4.0s, the same name on three takes 12.0s, and a lookup against a resolver that answers nothing takes 40.6s with the "budget" applying to none of it. One elapsed deadline now covers the lookup, every address and the handshake, with the lookup bounded by the only thread in this file, because `getaddrinfo` accepts no timeout at all. Measured after: 10.4s and 10.5s. And the VALUE moved from three seconds to ten, in the opposite direction from the fix. Three was chosen to make a test quick. A deadline that fires on a healthy-but-slow connect kills the whole job — there is no automatic retry engine for external steps, so a person has to notice and retry by hand — while a generous one costs at worst ten seconds of a stop nobody was promised any of. THREE STIMULI WERE BUILT AND THROWN AWAY before these tests measured anything, and each looked correct: an address in TEST-NET-3 fails in 0.1s, an unassigned address on the container's own subnet fails at the kernel's ~3s ARP timeout, and an unroutable resolver fails in 0.4s. Every one of them made its test pass against a node with no bound at all. What works is a peer that receives and stays silent: a route that drops, and a resolver of our own in a container. The multi-address test now verifies its stimulus really hangs here and skips if it does not. The tests also stopped synchronising on time. The TLS test waited on accept(), which is released before the client has sent its hello — so a node with an unbounded handshake could pass it on a lucky schedule — and the mid-body test proved bytes had reached a kernel and then slept half a second. The listener now reads before it sends and sends more than any buffer holds, so it announces only once a client has spoken and, where there is a body, only once the client has consumed it. A harness self-test holds the instrument to that, and the announce-on-accept mutation reds it. ROUND FOUR: THE CORRECTION COULD NOT BE SEQUENCED EITHER Review found that the redesign above fails on a fact this file already documents about its own uploads: a transport failure is AMBIGUOUS, and a store may accept a body after the client that sent it has gone. So when the success write times out and the cancellation is written next, the timed-out write can commit AFTER it. Reproduced by holding the receipt's upload for twelve seconds against a step that gives up at ten: the cancellation lands first, the success commits last, and the run ends `succeeded` beside exit 20 — the exact state the redesign existed to prevent. Sequential calls are not sequential commits. So the design got SMALLER rather than gaining a third mechanism. One receipt, or none: the flag is read once, before the document is composed; the write is protected and bounded; and if it fails, nothing else is written to that name. The exit code is decided with the document and never revised, so the two cannot tell different stories. `_stopped_after_the_work` is gone. WHAT MAKES THAT SAFE WAS MEASURED, NOT ASSUMED The design turns on what the platform does with a `succeeded` marker beside a launch it recorded as cancelled, so it was read at origin/master rather than guessed: * the outcome is decided from the orchestrator's own journal — _TERMINAL_LAUNCH_OUTCOMES keyed on the launch state (pipelines/external_finalize.py:254-260, :627-636); * a marker can only VETO a success, never claim one (:1371-1375); * a stopped attempt's objects are salvaged as diagnostics, role='logs' with no payload_kind — never published (:3213-3216, :3242-3243), and even a cancellation racing a collection demotes what was verified (:2769-2770); * the cascade sits behind the compare-and-set a cancellation wins (:2645-2651), and _cancel_execution never calls it; * what an operator reads quotes the marker's exit_code and error — never its status (:2384-2394); * the agent tests fence, hard stop, deadline and cancellation BEFORE exit 0 (agent/runner.py:2829-2843). So the residual state is not one the platform can act on: a step that finished its work and was interrupted while REPORTING it has genuinely succeeded, and the stop arrived late. That is what makes one document sufficient rather than merely simpler. THE RECEIPT NEEDED A CLOCK, AND THE DEADLINE LEAKED THROUGH A PROXY Nothing may abandon the receipt, so nothing but elapsed time can end it — and UPLOAD_TIMEOUT_S bounds SILENCE, not duration. Measured against a store that dribbles the answer out over forty seconds, never idle: 39.7s without a deadline, past the whole grace a stopped container gets. With one: 20s, sized against what the platform really promises — thirty seconds on the polite path (the agent's own hardcoded default, no caller overrides it), zero on any fence, and up to a heartbeat interval of notice latency before the SIGTERM is even sent. And the connect deadline was still spent twice behind an HTTPS proxy: the remainder was stored once as the socket timeout, and the TLS handshake after the tunnel re-used it. Measured with a proxy granting the tunnel after seven seconds: 17.6s for a ten-second deadline; 10.5s once the remainder is recomputed after CONNECT. A GUARD THAT COULD VANISH, AND A PREMISE THAT PROVED THE WRONG THING The multi-address premise check probed ONE address for two seconds and accepted 1.5 — which an address failing at the kernel's ~3s ARP give-up passes, while three of those cost ~9s under the broken implementation, inside the test's own threshold. The guard could have gone green against exactly what it exists to catch. It now probes the whole name and requires the timeout to have been spent once per address. And a skip no longer passes quietly: conftest fails any run containing a skip other than the verbatim-citation check, and names it. The stalling listener also stopped lying in the direction that makes tests pass: EOF or a socket error no longer announces a stall, and teardown now shuts down accepted connections before joining, so a thread blocked in recv or sendall is released rather than left parked. ROUND FIVE: THREE GUARDS THE DOCUMENT CLAIMED WERE NOT IN THE SUITE Review found that CONFORMANCE-BASELINE claimed mutation evidence for three tests — multi-address, name lookup, proxy — that no longer existed. The mutations had really been run; then an edit that replaced a SLICE of the test file between two anchors deleted all three while adding two others, and the claims stayed behind. For one commit the document described a suite that was not there, and the helpers those tests used sat in the harness with no callers: replacing the elapsed deadline with per-address timeouts, removing the bounded lookup, or deleting the recomputation after CONNECT would all have stayed green. The three tests are restored. And because a claim about a test is prose, and prose is not executable, the claim is now executable: verify_mutations.py patches each mutation, runs the named test, records whether it reds and on which assertion, restores, and exits non-zero if any claim is unsupported. Every liveness table in the baseline is replaced by its output: python verify_mutations.py -> 12/12 claims verified red against this suite Two of its own first runs are recorded in it, because both produced meaningless greens: a mutation must be patched onto the path the behaviour would really take (the "correct the receipt" patch first landed on a success path that scenario never reaches), and a patch target appearing twice is now REFUSED rather than resolved to the first match (the second version landed in a branch where its condition is dead). The rule going with it: never report mutation evidence for a test that is not in the committed suite at the moment of reporting. THE SAVE DEADLINE IS BEST-EFFORT, AND THE DOCUMENTS SAID OTHERWISE The twenty seconds was justified from a "fixed 30-second grace". Read at origin/master: nothing tells the container how long it has after a stop. Not the nine injected variables (agent/runner.py:2787-2802); not the credentials envelope, whose expires_at is a signature's lifetime (runners/credentials.py); not the job description, whose timeout_seconds is documented as "the REQUESTED runtime budget, not a deadline" (external/contract.py:485-489); and not the stop object the orchestrator composes on its heartbeat — inert end to end and read only by the agent (runners/jobs.py:123-157, agent/client.py StopInstruction "Nothing reads this yet"). Thirty is what every call site passes to docker stop today (agent/runner.py:2817, :2827, :3039) — an observation, not a promise, and the value is the agent's to choose. So there is nothing to clamp to, and the justification is withdrawn wherever it appeared: node.py's constant, the test's premise, AUTHORING's checklist, CONFORMANCE's testing guidance, CLAUDE.md and the baseline. What the number buys is a shape, not a guarantee — long enough for a receipt to land on a store that is working, short enough that a step which will not land one stops trying while there may still be time to say so — and the documents now point at exposing the real remaining deadline as the open platform task that would make it exact. SMALLER CORRECTIONS The skip guard killed expected xfails: pytest reports an expected xfail as skipped with wasxfail set, so the next expected_red_until_fixed test would have turned the session red and broken this repository's own documented mechanism. Excluded, and proved with a probe. Its exemption also matched by substring, so a future test named ..._verbatim_and_something_else would have smuggled a skip through; it compares the test's own name now. The receipt test justified asserting the status word by claiming it "is rendered into what an operator reads". It is not — the platform renders exit_code and error and never status, as this branch's own measurement says two hundred lines away. The assertion stays as a preference and now says so. README and AUTHORING promised the marker and the process "cannot" disagree. A SIGKILL landing after the marker commits and before the process returns leaves exit_code 0 beside the runner's 137, and no ordering closes that. They now claim what is true: the two never differ because of a DECISION. DOCUMENTS THAT SAID OTHERWISE AUTHORING.md's skeleton now shows the whole handler — flag first, then the shutdown, and no removal on close() — and says which wait cannot be interrupted and must be bounded instead. Its decision table, its checklist and CLAUDE.md's invariants gain the same three facts. The paragraph claiming reads get the longer timeout "because a stop landing during a read is noticed as soon as the next block arrives" is corrected; that sentence was the inert mechanism in prose. CONFORMANCE.md gains what this round learned about testing a stop: hold the response open past the grace, assert the marker when nothing has been produced yet, and test every wait, two of which need no store at all. README.md's test count and CONFORMANCE-BASELINE.md's numbers follow: 128 -> 140 passing, conforms_today 41 -> 52, basis_reference_quality 24 -> 35, basis_our_policy 23 -> 24, basis_contract unchanged at 82. The copyable skeleton teaches what landed — one receipt, protected, bounded, never corrected — and the checklist items that taught each withdrawn rule say plainly that they were wrong. What is still not measured, and cannot be here: that any of this is COLLECTED. A local SIGTERM models the node and nothing else. On the deadline path the terminal report is refused and the marker is never read; an operator's Cancel usually arrives as a SIGKILL. The receipt is written for the runs where it is read, and for the day those gaps close. Co-Authored-By: Claude Fable 5 --- CLAUDE.md | 38 +- CONFORMANCE-BASELINE.md | 375 +++++++++++++++++++- README.md | 12 +- conformance/docker.py | 128 +++++++ conformance/fakes3.py | 34 ++ conformance/stalling.py | 174 +++++++++ docs/AUTHORING.md | 160 ++++++++- docs/CONFORMANCE.md | 38 ++ node.py | 442 ++++++++++++++++++++--- tests/conftest.py | 59 +++ tests/test_cancellation.py | 710 +++++++++++++++++++++++++++++++++++-- tests/test_harness_self.py | 71 ++++ verify_mutations.py | 157 ++++++++ 13 files changed, 2295 insertions(+), 103 deletions(-) create mode 100644 conformance/stalling.py create mode 100644 verify_mutations.py diff --git a/CLAUDE.md b/CLAUDE.md index ceb375e..736c8cd 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -194,10 +194,40 @@ covered by a test, and none of them is enforced by the platform. so an inventory local to the work function strands everything already uploaded. Record an object *before* its upload starts: a store can accept a body after the client is gone, and an object nobody named is never looked at again. -6. **Handle SIGTERM.** This process is PID 1, and Linux gives process 1 no default signal - handling — without a handler the signal is discarded entirely. Set a flag, never do - work in the handler, and check the flag *between units of work* so a stop changes what - the step does next rather than only how it ends. +6. **Handle SIGTERM, and notice it without waiting for the network.** This process is + PID 1, and Linux gives process 1 no default signal handling — without a handler the + signal is discarded entirely. Set a flag, never do work in the handler, and check the + flag *between units of work* so a stop changes what the step does next rather than only + how it ends. The flag is not enough on its own: a process parked in a socket call + cannot read it, so the handler also shuts down the transport in flight. Two measured + facts decide the shape of that — closing the *response* does nothing (mid-read it + raises `reentrant call inside <_io.BufferedReader>` inside the handler, where it is + swallowed, and the read waits out its whole timeout), and a response does not exist at + all while the store is still deciding whether to answer. Registering the *connection* + and calling `shutdown` on its socket is what works, and it took this file from 12.2 + seconds to 0.2. Then ask it of every OTHER wait on the path, because that fix shipped + with two of them still open: the connection must go on the ledger before the call that + blocks, and it must NOT come off when `http.client` closes it after the headers of a + `Connection: close` response, or the ledger is empty for the whole body. Getting a + connection (DNS, TCP, TLS) cannot be interrupted at all — `ssl` detaches the socket + while wrapping it — so bound it with its own ELAPSED deadline and re-check the flag when + it returns. A timeout is not a deadline: `create_connection` spends yours once per + address, `getaddrinfo` ignores it entirely (so the lookup needs a thread), and a proxy's + CONNECT spends it a second time unless you recompute after the tunnel. Size it for a real + job — nothing retries an external step automatically. +7b. **One receipt, or none.** Decide what it says from the flag BEFORE composing it, protect + that write from your own handler, give it an elapsed deadline (a socket timeout measures + silence, not duration), and never write a second, correcting document to the same name: a + write that failed ambiguously may still be accepted and may commit after its own + correction. This repository shipped both repairs — abandonment, then correction — and + both lost the same way. Give that write an ELAPSED deadline (a socket timeout measures + silence), and size it knowing it is best-effort: **nothing tells the container how long + it has after a stop** — not the injected variables, not the credentials envelope, not + the job description, and the orchestrator's stop object stops at the agent — so no + positive number survives a remaining grace of zero. What makes that safe is measured on the platform side: the + orchestrator decides an outcome from its own journal, a marker can only veto a success, + a stopped attempt's objects are salvaged as diagnostics rather than published, and the + operator's sentence quotes `exit_code` and `error` but never `status`. 7. **Write the marker last**, and write one on the failure and cancellation paths too, with the real exit code and an inventory of whatever already landed. 8. **Classify exits honestly.** 0 succeeded, 1 a later attempt might survive, 10 no retry diff --git a/CONFORMANCE-BASELINE.md b/CONFORMANCE-BASELINE.md index 4ede471..16351f0 100644 --- a/CONFORMANCE-BASELINE.md +++ b/CONFORMANCE-BASELINE.md @@ -2,20 +2,36 @@ > ## Status: all twenty defects below are FIXED > -> `node.py` was rewritten and the whole suite is green, in both modes: +> `node.py` was rewritten and the whole suite is green, in every mode: > > ``` -> python -m pytest -q → 128 passed, 1 skipped -> python -m pytest -q --red-for-real → 128 passed, 1 skipped +> python -m pytest -q → 140 passed, 1 skipped +> python -m pytest -q --red-for-real → 140 passed, 1 skipped +> LSPO_ORCHESTRATOR_SRC=… LSPO_ORCHESTRATOR_REF=origin/master python -m pytest -q +> → 141 passed (the skip is the citation check; +> with the sources present it runs) +> python verify_mutations.py → 12/12 claims verified red against this suite > ``` > -> The two lines are now identical, which is the point: there is no `expected_red_until_fixed` +> **A skip other than that one now FAILS the run** (`tests/conftest.py`): a conditional test +> that skips has not run, and a guard that can disappear while the summary line stays green +> is the failure mode this repository keeps rediscovering. +> +> Those numbers were 128 for one release. Twelve tests were added since — eleven in +> `tests/test_cancellation.py` and one holding the harness's own stall instrument to +> account — and what they measure is in +> [the stop path was the right shape and inert](#the-round-after-the-stop-path-was-the-right-shape-and-inert) +> immediately below. Group counts today: `conforms_today` 50, `subject_is_platform` 67, +> `harness_self_test` 22, `expected_red_until_fixed` 0. Bases: `basis_contract` 82, +> `basis_reference_quality` 35, `basis_our_policy` 24. +> +> The first two lines are identical, which is the point: there is no `expected_red_until_fixed` > test left, so CI mode and the true result cannot differ. All twenty tests that used to be > red were moved into `conforms_today`, where a regression turns the run red immediately > rather than being absorbed as an expected failure. > -> **Everything below this box is the measurement that was taken BEFORE the repair, and it is -> kept deliberately.** It is the evidence for what each defect actually cost, and every one +> **Everything below the next section — *The round after* — is the measurement that was taken +> BEFORE the repair, and it is kept deliberately.** It is the evidence for what each defect actually cost, and every one > of them is a mistake a first version of a node makes — which makes it the most useful > reading in this repository for somebody about to write one. Read it as history, not as a > description of the file in this directory. @@ -35,6 +51,347 @@ > names. It is why the fix for the two-ports-one-filename collision disambiguates only > the names that actually collide, instead of namespacing every output by its port. +## The round after: the stop path was the right shape, and inert + +**The claim under test was that `node.py` does not handle a stop at all. It does** — and +had since the rewrite: a handler installed on SIGTERM and SIGINT, setting a flag and +nothing more; the flag checked between units of work; the inventory at module scope; a +marker written last, with `status: "cancelled"` and `exit_code: 20`, matching the code the +process returns. Every line of the shape `docs/AUTHORING.md` prescribes was there, and the +suite proved it. So the gap was somewhere else, and there were two of them. + +### 1. The mechanism that made the flag readable did nothing + +A flag cannot be read by a process parked in a socket call, and `node.py` knew that: it +kept a ledger of transfers in flight and its handler closed them. **Neither half worked**, +and both were measured directly rather than argued about: + +| What the file did | What was measured | +|---|---| +| put the **response** on the ledger | a response exists only once the store has begun to answer, so during the wait that matters the ledger is empty | +| called **`close()`** on it | mid-read that raises `RuntimeError: reentrant call inside <_io.BufferedReader>` *inside the handler*, where `contextlib.suppress` swallows it, and the read then waits out its whole timeout | + +So the real stop latency was the socket timeout, on both paths. Stopped during a held-open +download: **12.2 s**. During an upload: **10.2 s**. Against a store that never answers at +all — the case a stop actually has to survive — the read timeout is 25 s, and the container +took **25.2 s** to go, out of a nominal thirty that +[PROTOCOL.md](docs/PROTOCOL.md#7-cancellation) is explicit nobody is promised. + +The repair is on the **connection**, registered when its socket is created — before a byte +of a request is sent — and the handler calls `shutdown(SHUT_RDWR)`, which makes the pending +call return at once. Both schemes are covered: plain HTTP is what the harness and a local +demo exercise, TLS is what every presigned URL in production uses, and a fix that covered +only the first would have been invisible where it matters. Measured after: **0.22 s** and +**0.24 s** on the same two scenarios. One thing is deliberately exempt — once the marker is +being written, nothing may abandon it: there is nothing left to rescue by cutting that +connection and a whole run's account of itself to lose. + +That is one further act inside a signal handler, and `docs/AUTHORING.md` says a handler +sets a flag and does no work "and especially network work". **The ambiguity is real and it +is resolved rather than ignored**: a socket shutdown starts nothing, waits for nothing and +cannot block, so it is not work in the sense the rule is about — and the reason the rule +gives (that the cancellation path itself crashes) is why it is the last thing in the +handler and its failure is ignored. Nothing that *decides* anything moved into the handler. +The reasoning is in the code, at `_on_stop`. + +### 2. The harness never asked for the receipt + +Four cancellation tests, and not one of them required a marker to exist. The helper they +share returns early when there is none — deliberately, because the contract permits +silence — with the consequence that **a step which exits the instant it is signalled, +writing nothing at all, passed every one of them**. Prompt exit was measured; the account +of the run was not, and the account is the only thing salvage can publish from. + +That was proved rather than asserted: a copy of `node.py` that writes no marker on the stop +path still passes `test_a_step_stopped_during_a_download_does_not_claim_it_succeeded`, +`test_a_cancelled_step_stops_taking_on_new_work` and +`test_a_step_that_cannot_be_stopped_costs_the_whole_grace_period`. Only the fourth notices, +and only because that scenario has an object already on the ledger — stopped before it +produces anything, the old suite had nothing to say. + +Four tests close it, all `conforms_today`: + +| Test | What it forbids | +|---|---| +| `test_a_stopped_step_leaves_a_receipt_and_says_it_was_stopped` | being stopped and leaving no marker, or one that calls the ending anything but `cancelled` | +| `test_the_receipt_of_a_stopped_step_carries_the_code_the_process_returned` | the marker and the process telling two different stories, and an exit code that reads as "broken" rather than "stopped" | +| `test_a_stopped_step_claims_no_object_the_store_never_received` | a receipt that inventories an object nobody can find | +| `test_a_stop_is_noticed_without_waiting_for_the_transfer_it_landed_in` | a stop latency equal to the socket timeout, measured against a store that never answers | + +### All four are `basis_reference_quality`, and none of them may be anything else + +The temptation here is `basis_contract`, and it has to be refused for the sixth time. +`external/contract.py` does say *"A cancelled run still writes a marker: partial logs and +partial outputs are exactly what someone will want to look at afterwards"* — but it says it +while explaining what a field means, and everything the platform actually **does** with an +absent marker on this path treats it as an ordinary outcome: +`_salvage_what_the_step_produced` publishes *"what a FAILED or cancelled step managed to +write"* and returns an empty list when there is none, and the collector reports *"No +completion marker was written, so the step gave no account of itself and nothing it +produced could be salvaged"* as a finding, not a refusal. A marker is **required** only +after a reported success. Read literally, no rule makes any of these four behaviours a +violation, so labelling them as conformance would teach a preference as law — which is the +one mistake this document exists to keep correcting. + +The same goes for exit 20. `agent/runner.py` `_classify` asks +`if context.cancel_requested.is_set() or exit_code == EXIT_CANCELLED` and answers +`'cancelled'` either way, so nothing requires the code. Read the other way round, that line +is the whole argument for using it: **20 is the only signal that says "stopped" rather than +"broken" when the platform was not the party that asked.** + +### Liveness: one table, and it is executable + +Every row below was re-run against the suite **as it stands in this commit** by +`verify_mutations.py`, which patches the file, runs the named test, records whether it went +red and on which assertion, and restores. It exits non-zero if any claim is unsupported. + +``` +python verify_mutations.py → 12/12 claims verified red against the current suite +``` + +| Mutation | The test that reds, and on what | +|---|---| +| the SIGTERM handler is never installed | the receipt test — *"its receipt says 'succeeded'"*; and the promptness test — *"took 25.4s to go"* | +| `shutdown()` put back to `close()` | promptness — *"took 25.4s to go after being asked to stop, with a store that was never going to answer"* | +| the marker claims `outputs/ghost.csv`, never written | the over-claim test names the ghost | +| no marker on the stop path | the receipt test — *"wrote no completion marker: the store holds []"*; the other two **skip**, naming the legal ending | +| the ledger forgets a `will_close` connection after its headers | the mid-body test — *"took 25.9s while reading a body that had stopped arriving"* | +| one elapsed deadline replaced by the standard library's per-address spend | the multi-address test — *"spent 31.4s failing to reach a host with 3 addresses"* | +| the name lookup left unbounded | the lookup test — *"spent 43.1s on a name lookup that was never going to answer"* | +| the deadline not recomputed after a proxy's `CONNECT` | the proxy test — *"spent 20.4s getting a connection through a proxy that took seven of them to answer"* | +| the receipt corrected by a second document | the one-receipt test — *"wrote 2 completion markers for one run"* | +| the exit code revised after the document was written | the same test — *"the one receipt says the step exited 0 and it returned 1"* | +| the receipt's elapsed deadline removed | the drip test — *"spent 42.9s on a receipt whose answer was dribbled out over forty"* | +| the stalling listener announcing on `accept()` | the harness self-test — *"announced a stall before the client had said anything"* | + +### Why that script exists: this document once claimed three guards that were not here + +The multi-address, name-lookup and proxy tests were written, measured red under their +mutations, and reported — and then an edit that replaced a **slice of the test file between +two anchors** deleted all three while adding two others. The claims stayed. For one commit +this document described a suite that did not exist, and the three helpers those tests used +sat in the harness with no callers at all: replacing the elapsed deadline with per-address +timeouts, removing the bounded lookup, or deleting the recomputation after `CONNECT` would +every one of them have stayed green. + +Nothing caught it because **a claim about a test is prose, and prose is not executable**. +`verify_mutations.py` makes it executable, and two things it found on its own first runs are +worth keeping: + +* a mutation must be patched onto **the path the behaviour would really take** — the + "correct the receipt with a second document" patch first landed on the success path, where + in that scenario the first write has already timed out, so it never executed and reported + a green that said nothing; +* a patch target that appears **twice** is now refused rather than resolved to the first + match, because the second version of that same mutation landed in the work-failure branch, + where its condition is dead — again green, again meaningless. + +The rule that follows, and it is a rule about evidence rather than about code: **never +report mutation evidence for a test that is not in the committed suite at the moment of +reporting**. The script is how that is checked rather than remembered. + +**What is still not measured.** That any of this is *collected*. A local SIGTERM models the +node and nothing else: on the runtime-deadline path the terminal report is refused and the +marker is never read (the lease is clamped to the deadline, so `complete()` answers +`lease_lost`), and an operator's Cancel usually arrives as a SIGKILL. The receipt is +written for the runs where it is read, and for the day those gaps close. Nothing in this +repository can test that half. + +### The review of that round: the same defect, twice more, in the same file + +The repair above was shipped for review and came back with the finding that matters most +here — **it had the defect it was fixing, one layer up, twice.** "The object was not on the +ledger during the wait that matters" was fixed for exactly the wait that had been measured, +and there are four waits on this path, reached through different objects: + +| The wait | What it was doing | What it does now | +|---|---|---| +| getting a connection: DNS, TCP, **TLS handshake** | governed by the 25-second transfer timeout, and unreachable — `ssl` detaches the plain socket while wrapping it, so shutting that down raises `OSError: [Errno 9] Bad file descriptor` and the handshake runs to the timeout regardless (measured) | **bounded** by its own three-second budget, with the flag re-checked the moment the call returns so a stop that arrived during it does not go on to start a request | +| waiting for the store to begin answering | fixed last round | unchanged | +| **reading the body** | the ledger was empty: `http.client` closes the connection as soon as it has parsed the headers of a `Connection: close` response — which urllib sets on every request — and the `close()` override took the entry off | the override is gone; one request is in flight at a time, so the entry is simply replaced by the next connection | +| waiting for an upload to be acknowledged | fixed last round | unchanged | + +Measured on the shipped-and-reviewed version, both with a listener that accepts and then +says nothing: a stop during a stalled **TLS handshake** cost **25.2 s**, and a stop while a +**body had stopped arriving** cost **24.7 s** — the same 25-second timeout, twice, in the +release whose whole subject was not paying it. After: **3.2 s** (bounded, not cut) and +**0.3 s**. + +**The TLS half also closed a hole in what this suite can see at all.** Every presigned URL +in production is https and this harness's store is plain http, so a stop mechanism proved +only over http was a claim about the wrong protocol. It needed no certificate authority and +no `openssl`: a handshake stalls before any certificate is offered, so a listener that +accepts and refuses to speak is enough. `conformance/stalling.py` is that listener, and it +is also what produces the mid-body case, which the store's hooks cannot — they fire while a +request is still being authorised, which is before a byte of the response exists. + +### And the exception for a second stop was swallowing the first + +The same round introduced "nothing may abandon the receipt", and applied it to **every** +marker. A stop landing while a marker claiming SUCCESS was in flight therefore changed +nothing at all: the flag was set, the upload was left alone, it landed, and the step +returned **0** — a document saying `succeeded` inside a launch the orchestrator records as +cancelled, which is what `_step_account` renders for a human. Deterministic, not a race, +and measured: exit `0`, receipts written `['succeeded']`. + +The protection is now asymmetric, and the asymmetry is the argument that was made for it in +the first place. A receipt reporting a failure or a stop cannot be made worse by being cut +short, and it is the run's only account: protected. A receipt claiming success is the one +document a stop can turn into a lie: **not** protected — the handler cuts it, and the run +writes the cancellation it has become. The flag is checked again after that write, before +0 is returned, for the case where the receipt lands anyway. + +### The round after that: a retraction, and the same lesson a third time + +**The asymmetric protection argued for above is withdrawn.** It said: protect a receipt +reporting a failure or a stop, but leave one claiming SUCCESS abandonable, because that is +the document a stop can turn into a lie. The premise was right and the remedy was wrong. +Abandoning the upload does not prevent the lie — **it makes which document survives +unknowable.** Once the store has the whole body it may commit it, and cutting the socket +revokes nothing, so the cancellation written next is a second write to the same key that +can overlap the first. Neither this step nor object storage defines which of two +overlapping writes wins. The harness demonstrated it directly: its delay hook holds the +first commit back, the cancellation lands first, and the receipt the store serves is the +one saying `succeeded` — with the process exiting 20 beside it, which is worse than the +defect being fixed, because now the two accounts disagree as well. + +The test written for it made the same mistake one level up: **it looked away from the value +the store serves**, and said so in its own docstring, blaming the harness's hook. That is +the tell. A test that must avert its eyes from the property that matters is reporting a +design problem, not a harness problem. + +What replaces it: the receipt is protected whatever it says, the check happens **after** +that write, and the correction is a second write that begins only once the first has +finished. The writes are sequential, so the survivor is knowable, and the test now asserts +exactly it. This also makes the defence observable — the mutation that removes the check +was **green** last round, because the abandonment covered for it; it is red now, because +the check is the only thing standing there. + +### And the wait that was "bounded" was not bounded + +The three-second connect budget in that round was not an elapsed deadline, and could not +have been: `socket.create_connection` resolves the name **before there is a socket to apply +a timeout to**, and then applies the value **separately to each address it got back**. +Measured, in a container: + +| Stimulus | Behaviour | +|---|---| +| one silently-dropped address, `timeout=4` | 4.0 s | +| the same name on **three** such addresses, `timeout=4` | **12.0 s** — the number the caller passed, spent three times | +| a name lookup against a resolver that receives every query and answers none | **40.6 s**, with the step's "budget" applying to none of it | + +Both are now covered by one elapsed deadline (`_connect_within`, `_resolve_within`), and the +name lookup is bounded by handing it to a thread — the only thread in the file, and the +only way the standard library offers, since `getaddrinfo` takes no timeout at all. Measured +after: **10.4 s** and **10.5 s**. + +**And the value moved from three seconds to ten, in the opposite direction from the fix.** +Three was chosen to make a test quick, and the cost of that is asymmetric in a way that is +easy to get backwards: a deadline firing on a healthy-but-slow connect **kills the whole +job**, because there is no automatic retry engine for external steps — every failed attempt +is recorded as transient whatever the process returns, and a person has to notice and retry +it by hand (`docs/PROTOCOL.md` section 6). A generous deadline costs, at worst, ten seconds +of a stop nobody was promised any of. + +**Three stimuli were built and thrown away before one of these tests measured anything**, +and that is worth recording because each looked correct: + +* an address in TEST-NET-3 — fails in **0.1 s**, nothing is routed there and the kernel + says so; +* an unassigned address on the container's own bridge subnet — fails at **~3 s** whatever + timeout is asked for, because the kernel gives up on the ARP on its own schedule; +* an unroutable *resolver* — the lookup fails in **0.4 s** for the same reason. + +Each made its test pass against a node with no bound at all. What works is a peer that +receives and stays silent: a route that drops (`10.255.255.x`) and a resolver of our own in +a container (`docker.silent_resolver`), and the multi-address test now **checks that its +stimulus really hangs on this machine and skips if it does not**, rather than passing +quietly where the network refuses what it cannot route. + +> Liveness for every round is in [one executable table](#liveness-one-table-and-it-is-executable) +> near the top of this document, re-run by `verify_mutations.py`. The per-round tables that +> used to sit in each section have been folded into it: they restated the same claims, and one +> of them described a mechanism that a later round removed. + +### Round four: the correction could not be sequenced either, and the platform said so + +The redesign above — let the receipt land, then correct it — was reviewed and **fails on +the same fact this file already documents about its own uploads**: a transport failure is +ambiguous, and a store may accept a body after the client that sent it has gone. So when +the success write times out and the cancellation is written next, the timed-out write can +commit **after** it. Reproduced with the harness, holding the receipt's upload for twelve +seconds against a step that gives up at ten: the cancellation lands first, the success +commits last, and the run ends with `succeeded` beside exit 20 — the exact state the +redesign existed to prevent. **Sequential calls are not sequential commits.** + +So the design got smaller instead of gaining a third mechanism. **One receipt, or none:** +the flag is read once, before the document is composed; the write is protected; and if it +fails, nothing else is written to that name — the exit code and one log line are the whole +report, and the code is decided with the document so the two can never disagree. + +### What made that safe was measured on the platform, not assumed + +The question the design turns on is what the platform does with a `succeeded` marker beside +a launch it recorded as cancelled. It was read rather than guessed, at `origin/master`: + +| Question | Answer, and where it is written | +|---|---| +| What decides the execution's outcome? | The orchestrator's own journal. `pipelines/external_finalize.py:254-260` maps `ExternalLaunchState` to the outcome and `:627-636` branches on it; the recovery path branches on `attempt.state` (`:819`, `:856`, `:863`). | +| Can a marker claim a success? | No — it can only **veto** one. `:1371-1375` refuses a runner-reported success when the marker disagrees. There is no inverse. | +| Are a stopped run's objects delivered? | No. Salvage attaches them with `role='logs'` and no `payload_kind` (`:3213-3216`, `:3242-3243`); even a cancellation racing a collection demotes what was already verified (`:2769-2770`). | +| Does anything cascade downstream? | No. `_run_the_cascade` sits behind the compare-and-set in `_complete_execution` (`:2645-2651`), and `_cancel_execution` never calls it. | +| What does the operator read? | Our sentence first, then the marker's **`exit_code` and `error`** — `status` is never rendered (`:2384-2394`). A stopped container that wrote `succeeded, 0` produces *"The external job was cancelled. The step exited with code 0."* | +| Does the agent's exit code override? | No. `agent/runner.py:2829-2843` tests fence, hard stop, `deadline_hit` and `cancel_requested` **before** `exit_code == 0`. | + +**So the residual state is not a lie the platform can act on**, and a step that finished its +work and was interrupted while *reporting* it has genuinely succeeded — the stop arrived +late. That is what makes "write one document" sufficient rather than merely simpler. + +### The receipt is the one transfer that needs a clock — and the clock is a guess + +Nothing may abandon it, so nothing but elapsed time can end it — and `UPLOAD_TIMEOUT_S` is +not elapsed time. It bounds **silence**, so a peer that sends one byte per window holds the +transfer open indefinitely while never being idle. Measured with a store that dribbles the +receipt's answer out over forty seconds: **42.9 s** without a deadline. With one: **20 s**. + +**The twenty is best-effort by construction, and an earlier version of this document +justified it from a grace that was never promised.** Read at the deployed commit: nothing +tells the container how long it has after a stop. Not the nine injected variables; not the +credentials envelope, whose `expires_at` is a signature's lifetime; not the job description, +whose `timeout_seconds` is a *requested* budget with no start time attached; and not the +stop object the orchestrator composes on its heartbeat, which reaches the agent and stops +there. Thirty seconds is what today's build passes to `docker stop` at every call site — an +observation, not a guarantee, and the value is the agent's to choose. Against a remaining +grace of zero no positive deadline can be honoured, and the alarm may be killed before it +can log that it fired. What the number buys is a shape: long enough for a receipt to land on +a store that is working, short enough that a step which will not land one stops trying while +there may still be time to say so. Exposing the real remaining deadline to the workload is +an open platform task, and it is the thing that would make this exact. + +### The deadline still leaked through a proxy + +`_connect_within` computes the remainder through the lookup and the TCP connect and stores +it once, as the socket's timeout — and `HTTPSConnection.connect` then spends it *again* on +the TLS handshake behind a proxy's `CONNECT`. Measured against a proxy that grants the +tunnel after seven seconds and then goes silent: **17.6 s** for a ten-second deadline. The +remainder is recomputed after the tunnel now: **10.5 s**. + +### A guard that could vanish, and a premise that proved the wrong thing + +The multi-address test's premise check probed **one** address for two seconds and accepted +anything over 1.5 — which an address failing at the kernel's own ~3 s ARP give-up passes, +while three of those cost ~9 s under the broken implementation, comfortably inside the +test's own threshold. The guard could therefore have gone green against exactly what it +exists to catch. It now probes the whole name and requires the timeout to have been spent +once per address, which is the property the test depends on. + +And a skip no longer passes quietly: `tests/conftest.py` fails any run containing a skip +other than the verbatim-citation check, and names it. A conditional test that skips has not +run, and a guard that can disappear while the run stays green is the failure mode this +repository keeps rediscovering. + +--- + Measured, not reasoned about. Every line below is the observed behaviour of the image built from this repository's own `Dockerfile`, run as a container against the harness in `conformance/`, on Linux with Docker 28.4, with the citations checked against orchestrator @@ -612,7 +969,11 @@ than the original: instead of asserting a coupling, it now measures that the cou **Its liveness was measured, not assumed**, because a test that says "everything is readable" is exactly the shape that passes when nothing is being checked. Four mutations, -each run against real containers, and each has to fail for the *right* reason: +each run against real containers, and each has to fail for the *right* reason. (These +mutate the harness's own permission constants rather than the node, so they are not in +`verify_mutations.py`; what has been checked is that the test they name is still in the +suite — `tests/test_platform_rules.py` — because a table of mutations against a test that +no longer exists is exactly the failure recorded at the top of this document.) | Mutation | Result | |---|---| diff --git a/README.md b/README.md index 06a903d..223576a 100644 --- a/README.md +++ b/README.md @@ -9,7 +9,7 @@ whatever the container declares it produced. **`node.py` is safe to copy.** It passes the whole conformance suite: the harness in `conformance/` builds this repository's image, runs it as a real container and judges it -from the outside only, and **all 128 of its tests are green**. +from the outside only, and **all 141 of its tests are green**. That was not true until recently. Twenty tests used to be red, and [CONFORMANCE-BASELINE.md](CONFORMANCE-BASELINE.md) is the measured record of what each one @@ -28,10 +28,12 @@ one of which decides whether a real job survives: * it re-reads its credentials, so a run longer than fifteen minutes can still upload; * it keeps its inventory where the failure path can see it, and records an object before the upload starts; -* it handles a stop request, so a cancelled run stops taking on new work instead of - running to completion for nobody; -* it writes the completion marker last, on every path, with the exit code the process - really returns; +* it handles a stop request — stops taking on new work instead of running to completion + for nobody, and *notices* the stop instead of sitting in a socket call until it times + out, which is the half a handler usually leaves out; +* it writes the completion marker last, on every path, with the exit code it is about to + return — *about to*, because a kill landing between that document and the process's own + exit is a boundary nothing can make atomic; * it never prints a presigned URL. Read the label on any test before treating it as a rule: they do not carry the same diff --git a/conformance/docker.py b/conformance/docker.py index 144356e..dde8d8c 100644 --- a/conformance/docker.py +++ b/conformance/docker.py @@ -16,6 +16,8 @@ from __future__ import annotations +import contextlib +import ipaddress import json import os import re @@ -306,9 +308,20 @@ def start( user: str | None = None, entrypoint: str | None = None, command: tuple[str, ...] = (), + extra_hosts: tuple[tuple[str, str], ...] = (), + dns: tuple[str, ...] = (), + dns_options: tuple[str, ...] = (), ) -> Container: """Start one workload container, detached. + ``extra_hosts``, ``dns`` and ``dns_options`` exist for one question the harness cannot + ask any other way: how long does this node spend GETTING a connection? Repeating a name + in ``extra_hosts`` puts several addresses in the container's ``/etc/hosts``, which is + how a test produces a host whose addresses must each be tried; pointing ``dns`` at an + address nobody answers, with the resolver's own patience widened by ``dns_options``, + is how a test produces a name lookup that hangs. Both are properties of the container's + network, not of the store, so no fake server can express either. + ``unset_env`` names variables to REMOVE from the container's environment even if the image baked them in. ``docker run -e NAME`` with no ``=`` and no value on the host does exactly that — it drops the image's own ``ENV`` for that name. It is the only @@ -328,6 +341,12 @@ def start( '--log-opt', 'max-size=10m', '--log-opt', 'max-file=3', ] + for host, address in extra_hosts: + argv += ['--add-host', f'{host}:{address}'] + for server in dns: + argv += ['--dns', server] + for option in dns_options: + argv += ['--dns-option', option] for key, value in env.items(): argv += ['--env', f'{key}={value}'] for key in unset_env: @@ -348,3 +367,112 @@ def start( if out.returncode != 0: raise DockerUnavailable(f'docker run failed: {out.stderr.strip()}') return Container(name=name, started_at=time.monotonic()) + + +#: What the silent resolver prints once it is bound and dropping queries. Waiting for this +#: line is the difference between a test synchronised on evidence and one synchronised on a +#: guess: a resolver that has not bound yet answers with an ICMP refusal, which makes a +#: lookup fail in milliseconds and a test about a HANGING lookup pass for the wrong reason. +RESOLVER_READY = 'silent-resolver-bound' + +_SILENT_RESOLVER = f""" +import socket, sys +handle = socket.socket(socket.AF_INET, socket.SOCK_DGRAM) +handle.bind(('0.0.0.0', 53)) +print({RESOLVER_READY!r}, flush=True) +while True: + handle.recvfrom(4096) +""" + + +@contextlib.contextmanager +def silent_resolver(image: str, *, timeout: float = 30.0): + """A container that RECEIVES every DNS query and answers none. Yields its address. + + A name lookup only hangs if the query is delivered and ignored. An unroutable + nameserver does not do it — measured, inside a container: an address in TEST-NET-3 + fails in **0.4 s** with "Temporary failure in name resolution", because nothing is + routed and the kernel says so at once. A listener that swallows the packet gives the + resolver nothing to conclude, so it waits its configured patience, twice over, and the + lookup takes tens of seconds (measured: 20.0 s at ``timeout:5 attempts:2``). + + It has to be a container because port 53 is privileged in the HOST's namespace and this + harness must never need root; inside a container of its own it is ordinary. It reuses + the image this suite already built, so nothing is pulled. + """ + require_docker() + name = f'lspo-conformance-resolver-{uuid.uuid4().hex[:10]}' + started = subprocess.run( + ['docker', 'run', '--detach', '--rm', '--name', name, '--user', '0:0', + '--entrypoint', 'python3', image, '-c', _SILENT_RESOLVER], + capture_output=True, text=True, + ) + if started.returncode != 0: + raise DockerUnavailable(f'the silent resolver would not start: {started.stderr.strip()}') + try: + deadline = time.monotonic() + timeout + address = '' + while time.monotonic() < deadline: + logs = subprocess.run(['docker', 'logs', name], capture_output=True, text=True) + if RESOLVER_READY in (logs.stdout + logs.stderr): + found = subprocess.run( + ['docker', 'inspect', '-f', '{{.NetworkSettings.IPAddress}}', name], + capture_output=True, text=True, + ) + address = found.stdout.strip() + if address: + break + time.sleep(0.1) + if not address: + raise DockerUnavailable('the silent resolver never reported itself bound') + yield address + finally: + subprocess.run(['docker', 'kill', name], capture_output=True, text=True) + + +#: Addresses whose packets are DROPPED rather than refused, so a connect to one waits out +#: the caller's timeout instead of failing. Reaching them goes to the container's default +#: gateway, which has nowhere to send them and says nothing back. +#: +#: Three kinds of "unreachable" were measured from inside a container, and only the third +#: is any use for asking how long a step is prepared to spend connecting: +#: +#: * TEST-NET-3 (``203.0.113.7``) — fails in **0.1 s**: nothing is routed there and the +#: kernel says so at once; +#: * an unassigned address on the container's own bridge subnet (``172.17.255.254``) — +#: fails in **~3 s** whatever timeout is asked for, because the ARP for it goes +#: unanswered and the kernel gives up on its own schedule; +#: * these — **4.0 s against a 4-second timeout, and 12.0 s across three of them**, which +#: is the behaviour a test about connect budgets needs to see. +SILENTLY_DROPPED = ('10.255.255.1', '10.255.255.2', '10.255.255.3') + +_TIME_A_CONNECT = """ +import socket, sys, time +began = time.monotonic() +try: + socket.create_connection((sys.argv[1], 9), float(sys.argv[2])) +except Exception: + pass +print('%.2f' % (time.monotonic() - began), flush=True) +""" + + +def seconds_spent_connecting( + image: str, address: str, *, timeout: float = 2.0, extra_hosts: tuple[tuple[str, str], ...] = () +) -> float: + """How long a container spends failing to reach ``address``. For checking a premise. + + Whether a packet is dropped in silence or refused is a fact about the machine this + suite happens to run on, not about the node — so a test that needs a connect to HANG + has to establish that one does here, and say so rather than pass quietly when it does + not. This is what it asks with. + """ + require_docker() + argv = ['docker', 'run', '--rm'] + for host, host_address in extra_hosts: + argv += ['--add-host', f'{host}:{host_address}'] + argv += ['--entrypoint', 'python3', image, '-c', _TIME_A_CONNECT, address, str(timeout)] + done = subprocess.run(argv, capture_output=True, text=True) + if done.returncode != 0: + raise DockerUnavailable(f'the connect probe would not run: {done.stderr.strip()}') + return float(done.stdout.strip().splitlines()[-1]) diff --git a/conformance/fakes3.py b/conformance/fakes3.py index 9690046..2b003d4 100644 --- a/conformance/fakes3.py +++ b/conformance/fakes3.py @@ -145,6 +145,10 @@ class Request: #: become unauthorized because its body took a while to arrive. arrived_at: float = 0.0 fields: dict = field(default_factory=dict) #: the POST form fields, for an upload + #: Seconds to spend DRIBBLING the answer out, a byte at a time, instead of sending it. + #: A store that goes quiet and a store that answers slowly are different faults, and a + #: client can only tell them apart if it measures elapsed time rather than silence. + drip_for: float = 0.0 @dataclass @@ -628,10 +632,26 @@ def _store_or_refuse(self, request: Request, key: str, payload: bytes) -> None: self._error(refused) return endpoint._record_upload(request, key, payload) + if request.drip_for: + self._drip(b'HTTP/1.1 204 No Content\r\nContent-Length: 0\r\n\r\n', request.drip_for) + return self.send_response(204) self.send_header('Content-Length', '0') self.end_headers() + def _drip(self, answer: bytes, seconds: float) -> None: + """Answer one byte at a time, never pausing long enough to look idle. + + This is the shape a socket timeout cannot catch: every gap is short, so nothing + is ever "quiet", and yet the exchange takes as long as the store feels like. + A client that bounds only silence waits it out in full. + """ + per_byte = seconds / max(len(answer), 1) + for index in range(len(answer)): + self.wfile.write(answer[index:index + 1]) + self.wfile.flush() + time.sleep(per_byte) + # ----------------------------------------------------------------- errors def _error(self, refused: Refused) -> None: @@ -737,3 +757,17 @@ def hook(endpoint: 'Endpoint', request: Request) -> None: time.sleep(seconds) return hook + + +def drip_when(predicate, seconds: float): + """Answer the matching request a byte at a time, taking ``seconds`` over it. + + For the one property a socket timeout cannot express: a transfer that is never idle + and never ends. Everything else in this module models a store that goes QUIET. + """ + + def hook(endpoint: 'Endpoint', request: Request) -> None: + if predicate(request): + request.drip_for = seconds + + return hook diff --git a/conformance/stalling.py b/conformance/stalling.py new file mode 100644 index 0000000..294b599 --- /dev/null +++ b/conformance/stalling.py @@ -0,0 +1,174 @@ +"""A listener that says exactly as much as it is told to, and then nothing, for ever. + +This is not a store, and it deliberately speaks no HTTP of its own. It exists because the +fake store cannot express the two waits that decide whether a stop is noticed on the way +IN and on the way OUT: + +* **A TLS handshake that never completes.** The store is plain HTTP, and no request hook + can model a peer that accepts a connection and then refuses to negotiate. This one does + it by doing nothing at all — a handshake stalls before any certificate is offered, so no + certificate is needed to stall one, and the harness gains a TLS test without a + certificate authority, an ``openssl`` dependency, or a line of trust configuration in + the image. +* **A body that stops arriving half way.** ``Endpoint``'s hooks fire while a request is + still being authorised, which is BEFORE a single byte of the response is written, so a + delay there models "the store has not answered yet" and cannot model "the store answered + and then went quiet". The distinction matters because they are different waits in the + client, reached through different objects, and a node can be interruptible in one and + not the other — which is exactly what this repository shipped. + +**Every connection is announced on evidence, never on a timer**, and that is the whole +shape of :meth:`_serve`: read something first, send everything second, announce third. A +test that signalled as soon as the connection was ACCEPTED would be signalling before the +client had begun negotiating, and an implementation with an unbounded handshake could pass +it on a lucky schedule — the exact hole these tests exist to close. Reading first means the +client has really begun to speak; sending a preamble larger than any socket buffer means +``sendall`` cannot return until the client has really begun to listen. +""" + +from __future__ import annotations + +import socket +import threading +import time + +#: Localhost, for the one connection this module makes to itself: the wake-up that ends a +#: blocked ``accept``. Closing a listening socket from another thread does NOT reliably +#: wake one on Linux. +LOOPBACK = '127.0.0.1' + +#: What an HTTP proxy says when it has agreed to tunnel a connection. Sent late and +#: followed by silence, it produces the two-phase wait a proxied TLS connect really has. +TUNNEL_GRANTED = b'HTTP/1.1 200 Connection established\r\n\r\n' + + +def a_body_that_stops(sent: int = 16 * 1024 * 1024, promised: int = 64 * 1024 * 1024) -> bytes: + """Response headers promising ``promised`` bytes, followed by ``sent`` of them. + + ``sent`` is deliberately far larger than any socket buffer on either side. That is not + about volume: it is what makes the listener's own ``sendall`` unable to return until + the CLIENT has consumed most of it, which is the difference between "the bytes reached + a kernel" and "the client is inside the body read". Without it a test has only a sleep, + and a sleep proves nothing about a client it cannot see. + """ + headers = ( + f'HTTP/1.1 200 OK\r\nContent-Length: {promised}\r\nConnection: close\r\n\r\n' + ).encode('ascii') + return headers + b'x' * sent + + +class StallingEndpoint: + """Accept connections, read, send ``preamble``, announce, then say nothing for ever.""" + + def __init__(self, preamble: bytes = b'', *, answer_after: float = 0.0) -> None: + self.preamble = preamble + #: How long to hold the request before sending ``preamble``. A peer that answers + #: LATE and then goes quiet is a different shape from one that never answers, and + #: it is the shape a proxy has: the CONNECT is granted, slowly, and the TLS + #: handshake behind it then stalls. Whether the two waits share one budget or get + #: one each is invisible to any test where the first wait is instant. + self.answer_after = answer_after + #: Every connection accepted, kept so the sockets stay open. A closed socket would + #: end the client's wait, which is the one thing this class must never do early. + self.accepted: list[socket.socket] = [] + self._connected = threading.Event() + self._lock = threading.Lock() + self._listener = socket.socket() + self._listener.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) + self._listener.bind(('0.0.0.0', 0)) + self._listener.listen(8) + self.port = self._listener.getsockname()[1] + self._running = False + self._thread = threading.Thread(target=self._serve, daemon=True) + + def start(self) -> 'StallingEndpoint': + self._running = True + self._thread.start() + return self + + def stop(self) -> None: + """Shut down without leaving the serve thread blocked anywhere. + + There are three places it can be waiting, and closing a descriptor from another + thread does not reliably return any of them: + + * in ``accept``, for the next client — woken by connecting to ourselves; + * in ``recv``, for a client that connected and said nothing; + * in ``sendall``, for a client that spoke and then read nothing. + + The last two are why the accepted connections are shut down BEFORE the join rather + than after it. ``shutdown`` is what returns a syscall already in progress; ``close`` + on its own can leave the thread parked and the join times out silently. Whatever is + accepted during the wind-down is closed after the thread has gone, so nothing leaks + either way. + """ + self._running = False + self._release_accepted() + try: + with socket.create_connection((LOOPBACK, self.port), timeout=2.0): + pass + except OSError: + pass + self._thread.join(timeout=5.0) + self._release_accepted() + try: + self._listener.close() + except OSError: + pass + + def _release_accepted(self) -> None: + """Unblock and close every connection taken so far, however it is being used.""" + with self._lock: + accepted, self.accepted = list(self.accepted), [] + for connection in accepted: + for release in (lambda: connection.shutdown(socket.SHUT_RDWR), connection.close): + try: + release() + except OSError: + pass + + def url(self, host: str, *, scheme: str = 'http', path: str = '/held-open') -> str: + return f'{scheme}://{host}:{self.port}{path}' + + def wait_for_stall(self, timeout: float = 60.0) -> bool: + """Block until a client is really waiting on this listener. + + Not "until something connected": until it has spoken (so a TLS client has sent its + hello) and, when there is a preamble, until it has consumed nearly all of it (so an + HTTP client is inside the body rather than the headers). That is the moment worth + interrupting, and the only one these tests may signal on. + """ + return self._connected.wait(timeout) + + def _serve(self) -> None: + while self._running: + try: + connection, _ = self._listener.accept() + except OSError: + return # the listener was closed: teardown, not a fault + if not self._running: + connection.close() # the wake-up from stop(); nothing else to do + return + with self._lock: + self.accepted.append(connection) + try: + spoken = connection.recv(4096) # the ClientHello, or the HTTP request line + if not spoken: + continue # it connected and closed without asking for anything + if self.answer_after: + time.sleep(self.answer_after) + if self.preamble: + connection.sendall(self.preamble) + except OSError: + continue # it went away mid-exchange: nobody is stalled on us + # Announced ONLY on the success of both, and the ``continue``s above are the + # point. Announcing after an EOF or a broken pipe would be the instrument + # lying in the direction that makes tests pass: a test would signal its + # container believing a client was parked here, when the client had gone. + self._connected.set() + + def __enter__(self) -> 'StallingEndpoint': + return self.start() + + def __exit__(self, *exc) -> None: + self.stop() diff --git a/docs/AUTHORING.md b/docs/AUTHORING.md index 7941d6c..50c5dd0 100644 --- a/docs/AUTHORING.md +++ b/docs/AUTHORING.md @@ -131,6 +131,7 @@ import hashlib import json import os import signal +import socket import sys import tempfile import time @@ -148,12 +149,59 @@ class Permanent(Exception): # RECOMMENDATION. PID 1 receives SIGTERM only because we install this. The # handler sets a flag; ordinary control flow decides what to do about it, which # is what keeps the partial inventory and lets the marker still be written. +# +# RECOMMENDATION, and this is the half that gets left out — including by the +# first version of this repository's own node.py, which is where the two facts +# below were measured rather than reasoned about. A flag cannot be read by a +# process parked in a socket call, so the handler must also make that call +# return, or your stop latency is your network timeout and nothing else. +# +# * Closing the RESPONSE object does not do it. Mid-read it raises +# "reentrant call inside <_io.BufferedReader>" INSIDE the handler, where you +# will never see it, and the read then waits out its whole timeout anyway. +# * A response does not exist yet while the store is still deciding whether to +# answer, so a ledger of responses is empty during the wait that matters. +# +# Shutting the socket down does do it, and it works from the moment the +# connection is made. Nothing here starts anything or waits for anything, which +# is the line this rule is really drawing. +# +# BEHAVIOUR, and it decides one of your timeouts. There is one wait on this path +# that no signal can shorten: DNS, the TCP connect and the TLS handshake happen +# inside a single call that hands out no socket anybody else can reach — `ssl` +# detaches the plain socket while wrapping it, so shutting THAT down raises +# "Bad file descriptor" and the handshake runs to its timeout regardless +# (measured). What cannot be interrupted has to be bounded: give getting a +# connection its own short budget, separate from the timeout you allow a +# transfer, and re-check the flag the moment the call returns so a stop that +# arrived during it does not go on to start a request nobody wants. CANCELLED = False +# The transport of the request in flight, put here by whatever opens the +# connection — in node.py, a small HTTPConnection subclass that adds itself in +# connect(). It does NOT remove itself in close(): http.client closes the +# connection as soon as it has parsed the headers of a `Connection: close` +# response, which urllib sets on every request, so a ledger that forgets a +# connection there is empty for the whole of the body. +IN_FLIGHT = [] + + +# RECOMMENDATION. One transfer is exempt: the receipt. Cutting that upload +# saves nothing — the work is over and everything else is written — and costs +# the run its only account of itself. It gets a deadline instead (see main). +WRITING_THE_RECEIPT = False def _on_sigterm(signum, frame): global CANCELLED + # The flag FIRST, then the socket. If the shutdown throws, this step is + # exactly as stopped as it would have been without it, and ordinary control + # flow still sees the flag at its next check. CANCELLED = True + if WRITING_THE_RECEIPT: + return + for transport in list(IN_FLIGHT): + with contextlib.suppress(Exception): + transport.shutdown(socket.SHUT_RDWR) signal.signal(signal.SIGTERM, _on_sigterm) @@ -295,7 +343,16 @@ def write_marker(creds, manifest, status, exit_code, error=None, ports=None): 'error': error, } body = json.dumps(marker, sort_keys=True, indent=2).encode('utf-8') - _write_raw(creds.get(force=True), MARKER_FILENAME, body) # fresh credentials + # RECOMMENDATION. Protected from the stop handler, and bounded by a clock of + # its own. Those two go together: the moment nothing may abandon this + # transfer, nothing but elapsed time can end it, and a socket timeout is not + # elapsed time — it measures silence, so a peer sending one byte per window + # holds you open for as long as it likes. Size the deadline under whatever + # grace the platform gives a stopped container. + global WRITING_THE_RECEIPT + WRITING_THE_RECEIPT = True + with _elapsed_deadline(RECEIPT_DEADLINE_S): # shuts IN_FLIGHT down when it fires + _write_raw(creds.get(force=True), MARKER_FILENAME, body) # fresh credentials def main(): @@ -326,8 +383,24 @@ def main(): print(f'node: could not write the marker: {_redact(marker_failure)}', file=sys.stderr, flush=True) return code - write_marker(creds, manifest, 'succeeded', EXIT_OK, ports=ports) - return EXIT_OK + # RECOMMENDATION, and it is the one this document got wrong twice. Decide what + # the receipt says ONCE, from the flag, before composing it — and if the write + # fails, do not write a different receipt to the same name afterwards. A write + # that fails ambiguously may still be accepted, so a "correction" can commit + # first and the thing it corrected can land on top of it: two documents for one + # run, and no defined winner. The exit code is decided with the document and is + # not revised either, so they never differ by decision — only ever because a kill + # landed between the document and this process's own exit, which nothing can prevent. + stopped = CANCELLED + status, code = ('cancelled', EXIT_CANCELLED) if stopped else ('succeeded', EXIT_OK) + try: + write_marker(creds, manifest, status, code, ports=ports) + except Permanent as exc: # nothing was offered to the store + print(f'node: no valid marker could be written: {_redact(exc)}', file=sys.stderr, flush=True) + return EXIT_PERMANENT + except Exception as exc: # it may or may not be there; say so, write nothing else + print(f'node: the {status} marker could not be confirmed: {_redact(exc)}', file=sys.stderr, flush=True) + return code if __name__ == '__main__': @@ -344,11 +417,11 @@ the obvious alternative fails on a real run, later, saying something unrelated: | Credentials behind an accessor | The file is replaced under you, without a signal. An accessor makes "re-read near expiry" one line instead of a decision at every call site. | | `force=True` before the marker | The marker is written last, which on a long run is the moment the original envelope is most likely to be dead. | | Bootstrap in its own `try` | Before credentials exist there is nowhere to write a marker. That failure has to be reported on stderr and by exit code alone. | -| Signal handler sets a flag only | Doing work, and especially network work, inside a signal handler is how the cancellation path itself crashes. | +| Signal handler sets a flag, and abandons the transfer in flight | Doing work, and especially network work, inside a signal handler is how the cancellation path itself crashes — so nothing there decides anything, and its one further act cannot block: a socket shutdown starts nothing and waits for nothing. Without it the flag is unreadable for as long as your socket timeout, because the process is inside the call. | | Streaming everywhere | 1 GiB permitted per object against 2 GiB of container memory. An OOM kill leaves the process no chance to write a marker. | | Inputs fetched one at a time, and deleted | Nothing bounds the size, the total or the count of your inputs, and the container has no disk quota. Keeping them all is how a node fills the customer's disk. | | Comparing envelopes with `==`, not `is` | Each read parses a new object, so an identity test is always "changed" and the retry guard never fires. | -| Exit code passed into the marker | So the marker and the process cannot tell two different stories about one run. | +| Exit code passed into the marker | So the marker and the process do not tell two different stories about one run. Not *cannot*: a SIGKILL landing after the marker commits and before your process returns leaves your `exit_code: 0` beside the 137 the runner observes, and no ordering of yours closes that. What this buys is that the two never differ because of a DECISION you made. | --- @@ -381,12 +454,17 @@ Two things in `node.py` are still worth pointing at rather than copying blindly: upload with it needs a further dependency. The standard library does it in about sixty lines. If you bring your own HTTP client, check what it does with a large body before you trust it. -* **Its two network timeouts differ on purpose.** Reads get longer than uploads, because a - stop landing during a read is noticed as soon as the next block arrives — the handler - closes the response underneath it — while a stop landing after an upload's body has been - sent cannot be shortened by anything at all: the step is waiting for the store's answer, - and only the timeout bounds that wait. Size it well inside whatever grace a stop is - given. +* **Its two network timeouts differ on purpose, and neither of them is its stop latency.** + That sentence used to read the other way round here — reads were given the longer + timeout because a stop was said to be noticed "as soon as the next block arrives", and + uploads the shorter one because after the body has been sent "nothing can shorten that + wait". The first half was measured and found false, which is what produced the socket + shutdown in the skeleton above; the second half is false for the same reason. A stop is + noticed at once on both paths now, and the timeouts bound something else entirely: a + store that has gone quiet with nobody signalling anything. The upload's is the shorter + of the two because an upload's ending is the ambiguous one — the store may already have + committed the object — so waiting longer only buys a clearer answer about something that + has already happened. One thing that is **not** a defect: `node.py` claims `result.json` under a `report` port rather than under `output`. Both are legal. The orchestrator's own test of its example @@ -495,6 +573,66 @@ apart either treats advice as law or treats law as advice. Both are expensive. * [ ] **RECOMMENDATION.** A SIGTERM handler sets a flag; the work loop checks it; the stopped path writes a marker and exits 20. Without a handler your process, as PID 1, discards the signal entirely. +* [ ] **RECOMMENDATION, and it is the one that is usually missing from a handler that + exists.** The handler also makes the network call you are inside return — shut the + socket down; closing the response does nothing (see the skeleton). A handler that + only sets a flag leaves your stop latency equal to your socket timeout, which on a + stop that gives you no warning is the difference between a receipt and silence. +* [ ] **RECOMMENDATION.** Ask that question of **every** wait on the path, not the one you + thought of first. There are four, and they are reached through different objects: + getting a connection (DNS, TCP, TLS), waiting for the store to begin answering, + reading the body, and waiting for an upload to be acknowledged. This repository + fixed the second, shipped it, and had the first and third still costing the full + timeout — the same defect twice more, in the same file, a week apart. +* [ ] **RECOMMENDATION.** Give **getting a connection** its own deadline, separate from the + timeout you allow a transfer: it is the one wait nothing can interrupt, so its length + IS your stop latency there. Two traps, both measured. **A timeout is not a deadline:** + `socket.create_connection` resolves the name before there is a socket to time, then + applies your number *separately to each address* — one name on three addresses spent + 12 seconds of a 4-second "timeout". And **`getaddrinfo` takes no timeout at all**, so + a sick resolver hangs you for as long as `/etc/resolv.conf` says to be patient + (measured: 40 s), inside a call owning no socket, which is also where a receipt you + have promised not to abandon goes to die. Bounding the lookup needs a thread. +* [ ] **RECOMMENDATION.** Choose that number for a real job, not for a quick test. A + deadline that fires on a healthy-but-slow connect kills the whole run: nothing retries + an external step automatically, so a person has to notice + ([PROTOCOL.md](PROTOCOL.md#6-exit-codes)). Generous costs you seconds of a stop; tight + costs somebody a job. +* [ ] **RECOMMENDATION, and this document has now been wrong about it twice.** Write + **one** receipt, or none. Decide what it says from the stop flag *before* you compose + it, protect that write from your own handler, and if it fails do **not** write a + different receipt to the same name afterwards — report the ambiguity through your exit + code and your log and stop there. Neither repair that suggests itself works: cutting + the upload does not revoke a body the store already has, and following it with a + correction races it, because a write that failed ambiguously may still be accepted and + may commit *after* the correction. Sequential calls are not sequential commits, and + two documents for one run have no defined winner. +* [ ] **BEHAVIOUR, and it is why the paragraph above can be so relaxed.** A receipt saying + `succeeded` beside a launch the platform recorded as cancelled is not a state the + platform can act on. The outcome is decided from the orchestrator's own journal; a + marker can only ever *veto* a success, never claim one; a stopped attempt's objects are + salvaged as diagnostics with no output port, so nothing is delivered; the cascade sits + behind a compare-and-set a cancellation wins; and the sentence an operator reads quotes + your `exit_code` and `error`, never your `status`. A step that finished its work and + was interrupted while *reporting* it has genuinely succeeded — the stop arrived late, + and there is nothing to correct. +* [ ] **RECOMMENDATION.** Give that protected write a deadline of its own, in elapsed time. + The two go together: the moment nothing may abandon a transfer, nothing but a clock can + end it — and a socket timeout is not a clock, it measures silence, so a peer sending one + byte per window holds you open indefinitely while never being idle. +* [ ] **BEHAVIOUR you must size that deadline against, and it is uncomfortable.** **Nothing + tells your container how long it has after a stop.** Not the injected variables, not the + credentials envelope (its `expires_at` is a signature's lifetime), not the job + description (`timeout_seconds` is a *requested* budget with no start time attached), and + not the stop object the orchestrator composes on its heartbeat — that reaches the agent + and stops there. The interval before the kill is the agent's to choose and can be + nothing at all. So a save deadline of your own is **best-effort by construction**: no + positive number can be honoured against a remaining grace of zero, and your alarm may be + killed before it can log that it fired. Choose one anyway — long enough that a receipt + lands on a store that is working, short enough that a step which will not land one stops + trying while there may still be time to say so — and do not write down a justification + that depends on a grace nobody gave you. The number worth wanting is the remaining stop + deadline itself, which is an open platform task. * [ ] **BEHAVIOUR to know while you write that handler, because it decides what it is worth.** **Neither of the two stops named here preserves what you write.** An **operator pressing Cancel** usually does not reach your process at all — it normally diff --git a/docs/CONFORMANCE.md b/docs/CONFORMANCE.md index eb5179c..65c5f5e 100644 --- a/docs/CONFORMANCE.md +++ b/docs/CONFORMANCE.md @@ -393,6 +393,44 @@ measure it against, because no interval on any stop path is guaranteed ([PROTOCOL.md](PROTOCOL.md#7-cancellation)). A node that needs the whole of a stop's notional grace is a node that gets nothing done on a stop that gives it none. +**RECOMMENDATION, and it is the one this repository learned the hard way.** Make the store +in your test hold a response open **longer than the stop is nominally given**, and stop the +container during that. A store that eventually answers lets a step which merely *waited* +look exactly like a step that stopped — every timing assertion passes, for the wrong +reason. Held open past the grace, the two are no longer confusable, and it is the shape +that caught `node.py` handling a stop correctly in every respect except noticing it: +12.2 seconds to go, because its handler closed the wrong object. See +`tests/test_cancellation.py` for both halves — the timing, and the receipt — and +[AUTHORING.md](AUTHORING.md#the-skeleton) for what a handler has to do to pass them. + +**RECOMMENDATION, and it is worth more than the rest of this section.** Test **every wait** +your step can be stopped inside, not the one you thought of first. There are four — +getting a connection (DNS, TCP, TLS), waiting for the store to begin answering, reading the +body, and waiting for an upload to be acknowledged — and they are reached through different +objects, so a node can be interruptible in one and not the others. This repository fixed +the second, shipped it, and still paid the full 25-second timeout on the first and the +third. Two of the four need no store at all to test: a listener that accepts a connection +and then says nothing stalls a **TLS handshake** (no certificate is involved — a handshake +stalls before any certificate is offered), and the same listener sending response headers +that promise more body than it delivers stalls a **read mid-body**. Roughly forty lines, +no new dependency; `conformance/stalling.py` is the whole of it. + +**BEHAVIOUR, and it caps what any of these tests can prove.** A local SIGTERM followed by +a kill after N seconds is your harness's number, not the platform's. The agent chooses what +to pass to `docker stop`, a fence passes nothing at all, and — measured at the deployed +commit — **no channel tells your container how much time it has left**: not the injected +variables, not the credentials envelope, not the job description, and the stop object the +orchestrator composes on its heartbeat reaches the agent and goes no further. So a timing +test proves your node bounds ITSELF; it cannot prove the bound will be honoured, and a +document that says otherwise is describing a promise nobody made. + +**RECOMMENDATION.** Assert that a marker exists **even when your step had produced nothing +yet**. That case is easy to leave untested and it is where the hole hides: a step that +exits the instant it is signalled, writing nothing at all, satisfies every assertion about +promptness and every assertion about not over-claiming. This suite had that hole for a +release — a stop landing during the first download was measured for its speed and never for +its account of itself. + **BEHAVIOUR, and it decides what this test is evidence of.** A local SIGTERM models your node's own behaviour on a stop, and nothing more. It is not a model of what the platform then does with the result, on any of the three stop paths. An **operator pressing diff --git a/node.py b/node.py index 2a36db7..66113a3 100644 --- a/node.py +++ b/node.py @@ -64,9 +64,14 @@ 3. **It keeps its inventory where the failure path can see it.** Salvage publishes only what the marker lists, so an inventory local to the work function strands everything already uploaded. -4. **It handles a stop request.** This process is PID 1 in its container, and Linux - gives process 1 no default signal handling: without a handler, SIGTERM is discarded - entirely and the step runs to completion for a run nobody will collect. +4. **It handles a stop request, and notices it without waiting for the network.** This + process is PID 1 in its container, and Linux gives process 1 no default signal + handling: without a handler, SIGTERM is discarded entirely and the step runs to + completion for a run nobody will collect. Installing the handler is only half of it — + a step that installs one and then sits in a socket call until it times out has spent + the whole of a grace it was never promised, so the handler also abandons the transfer + in flight. See :class:`_StoppableTransport` for what that takes and what the obvious + version of it does instead, which is nothing. 5. **It never prints a credential.** A presigned URL's query string IS a read credential for that object, and container output is stored with the execution, shown to everyone who can see the run, and searchable. @@ -91,14 +96,17 @@ import contextlib import datetime import hashlib +import http.client import io import json import logging import os import re import signal +import socket import sys import tempfile +import threading import time import urllib.error import urllib.request @@ -131,14 +139,54 @@ #: The upload policy refuses a single object above this. MAX_OBJECT_BYTES = 1024 * 1024 * 1024 -#: Socket timeout for one read. A stop landing during a read is noticed as soon as the -#: next block arrives, because the handler closes the response underneath it. +#: Socket timeout for one read. It bounds a store that has gone quiet — NOT how long a +#: stop takes to be noticed, which is what this constant used to claim. A stop is noticed +#: at once, because the handler shuts the socket down underneath the call +#: (:class:`_StoppableTransport`); this number is what is left for the case where nobody +#: signalled anything and the other side simply stopped answering. READ_TIMEOUT_S = 25.0 -#: Socket timeout for one upload — deliberately shorter. Once the body has been sent the -#: step is waiting for the store's answer, and there is nothing left to close: no signal -#: can shorten that wait, so the timeout is the only thing that bounds it. It has to stay -#: well inside the grace a stop is given, or ignoring a stop costs a runner slot. +#: An ELAPSED deadline for getting a connection — the name lookup, every address tried, +#: and the TLS handshake that follows, together. It exists because that whole stretch is +#: the one a stop CANNOT interrupt: it hands out no socket anybody else can reach, and +#: Python's ``ssl`` detaches the plain socket while it wraps it, so shutting that down +#: raises "Bad file descriptor" rather than ending the handshake (measured). What cannot +#: be interrupted has to be bounded. +#: +#: **Elapsed, and that word is the whole of it.** Passing a timeout to +#: ``socket.create_connection`` does NOT bound this: it resolves the name first, with no +#: timeout applied to that at all, and then applies the value **separately to each address +#: it got back** — so a slow resolver is unbounded and a host with four addresses can take +#: four times what you thought you asked for. :func:`_connect_within` is what makes one +#: number mean one number. The handshake that follows inherits whatever is left of it. +#: +#: **Ten seconds, and it is chosen against what a real job needs, not against what makes a +#: test quick.** Reaching an object store is milliseconds, so this is enormous headroom — +#: deliberately, because the cost of being wrong is asymmetric in a way that is easy to get +#: backwards. A deadline that fires on a healthy-but-slow connect **kills the whole job**: +#: there is no automatic retry engine for external steps, every failed attempt is recorded +#: as transient whatever this process returns, and somebody has to notice and retry it by +#: hand (``docs/PROTOCOL.md`` section 6). A deadline that is generous costs, at worst, ten +#: seconds of a stop nobody was promised any of. Ten is the point where a stall is +#: unambiguous and a working network is nowhere near. +CONNECT_DEADLINE_S = 10.0 +#: Socket timeout for one upload — deliberately shorter, because an upload's ending is the +#: ambiguous one. Once the body has been sent the store may already have committed the +#: object, so waiting longer buys only a clearer answer about something that has already +#: happened, and this step has recorded that object either way. UPLOAD_TIMEOUT_S = 10.0 +#: An ELAPSED deadline for writing the completion receipt, covering the connection and the +#: upload together. The receipt is the one thing this step will not abandon on a stop, so +#: it is the one thing that needs its own clock: :data:`UPLOAD_TIMEOUT_S` bounds a socket +#: going QUIET, not a transfer taking long, and a peer that sends a byte every few seconds +#: keeps a connection alive for as long as it likes. +#: +#: **Twenty seconds, against a grace of thirty that nobody promises.** Thirty is the +#: agent's own constant, hardcoded as a default and passed by no caller, so it is the most +#: the polite path can ever give (``agent/executors/docker_exec.py`` ``stop``); a fence +#: gives zero, and a cancellation may not even be noticed until the next heartbeat. Twenty +#: leaves the process room to exit and say why before the kill lands, and a receipt that +#: cannot be written in twenty seconds was not going to be written. +RECEIPT_DEADLINE_S = 20.0 #: Every streaming copy moves this much at a time. CHUNK_BYTES = 1024 * 1024 #: How much a streaming copy may leave in the kernel's page cache before asking for it @@ -167,24 +215,269 @@ class _Expired(TransientError): #: Set by the signal handler; read by ordinary control flow. Never do work in a handler. CANCELLED = False -#: Transfers currently in flight. The handler closes them, which is what turns "the step -#: was asked to stop" into an immediate return from a socket read that would otherwise -#: block for as long as the other side felt like holding it open. Without this, a stop -#: that lands inside a transfer is not noticed until the transfer ends on its own. -_IN_FLIGHT: set = set() +#: The transport of the request in flight — one, because this program makes exactly one +#: request at a time. A copy of this file that overlaps requests needs a set here instead. +_IN_FLIGHT: list = [] + +#: Whether the handler may still abandon what is in flight. It may not once the receipt is +#: being written: by then there is nothing left to rescue by cutting a connection, and a +#: whole run's account of itself to lose. A second stop CAN arrive — the agent asks for one +#: from three different places — and the kill behind it is what bounds this wait anyway. +_ABANDONABLE = True + + +class _StoppableTransport: + """An HTTP connection the stop handler can reach — for every wait that can be reached. + + Mixed into whatever connection class urllib chose (:func:`_stoppable_version_of`). + This file's first attempt kept the RESPONSE object on the ledger and called + ``close()`` on it, and that fails twice over: + + * **Too late.** A response exists only once the store has begun to answer, so a stop + landing while the step was still waiting for the first byte of a GET reached nothing + at all, and was noticed only when the socket timed out — measured at the full length + of a held-open response, out of a grace that is nominally thirty seconds and + guaranteed to be nothing at all. + * **Wrong call.** ``close()`` does not interrupt a read that is ALREADY blocked. + Measured: mid-body it raises ``RuntimeError: reentrant call inside + <_io.BufferedReader>`` from inside the handler — where the exception is swallowed — + and the read then waits out its whole timeout regardless. ``shutdown()`` makes the + pending call return immediately, which is the entire point of keeping this ledger. + + **The same question has to be asked of every OTHER wait on this path**, which is what + the shape below is about. There are four, and they are not alike: + + 1. **DNS, the TCP connect and the TLS handshake.** All three happen inside one call, + which hands out no socket anybody else can reach: ``ssl`` detaches the plain socket + while it wraps it, so shutting that down raises ``OSError: [Errno 9] Bad file + descriptor`` instead of ending the handshake (measured — the handshake then ran to + the full read timeout regardless). Nothing here can be interrupted, so it is + BOUNDED instead, by :data:`CONNECT_DEADLINE_S` — one ELAPSED deadline over the + lookup, every address and the handshake, because the timeout the standard library + accepts here is none of those things (:func:`_connect_within`). The flag is + re-checked the instant the call returns, so a stop that arrived during it does not + go on to start a request nobody wants. + 2. **Waiting for the store to begin answering.** Interruptible, and the reason the + connection goes on the ledger before a byte is sent rather than after. + 3. **Reading the body.** Interruptible — but only if the connection is still ON the + ledger, which is why there is no ``close()`` override here. ``http.client`` + calls ``close()`` on the connection as soon as the headers of a ``will_close`` + response are parsed (and urllib sets ``Connection: close`` on every request), so + removing the entry there would empty the ledger for the whole of the body. + 4. **Waiting for a store to acknowledge an upload.** Interruptible, same mechanism. + + The socket is also remembered in an attribute of our own, because urllib drops its + reference to it the moment the response exists (``h.sock = None``, in + ``AbstractHTTPHandler.do_open``) while the response goes on reading through it. + """ + + def connect(self): + # On the ledger BEFORE the call that blocks rather than after it. Be exact about + # what that buys, because the obvious claim is wrong: nothing can be shut down + # during the call below — there is no socket yet, and the one ``ssl`` builds is + # detached from this object while it handshakes (note 1). What bounds that stretch + # is the deadline, and what acts on a stop is the check after it. The entry is + # still made here because the ledger should never say "nothing in flight" while a + # transfer is being set up, and it costs one assignment. + _IN_FLIGHT[:] = [self] + wanted = self.timeout + self._deadline = time.monotonic() + CONNECT_DEADLINE_S + # ``_create_connection`` is an instance attribute ``http.client`` sets in its own + # ``__init__``, so this replaces it rather than overriding a method — a method + # would be shadowed by that attribute and silently never called. + self._create_connection = lambda address, timeout, source=None: _connect_within( + address, self._deadline, source + ) + super().connect() + # Getting here was the deadline's business. Everything after it is a transfer, and + # transfers get the timeout the caller asked for. + if wanted: + self.sock.settimeout(wanted) + self._transport = self.sock + if CANCELLED: + # The stop landed inside a phase nothing could interrupt. It is over now, and + # this is the first moment ordinary control flow gets a say: do not go on to + # send a request for a run that has been called off. The receipt is exempt — + # it is the one request a cancelled run still has to make. + if _ABANDONABLE: + raise _Stopped('stop requested while this connection was being made') + + def _tunnel(self): + """Granting the tunnel spends the deadline too, so what follows gets what is LEFT. + + With a proxy configured there are TWO waits inside one ``connect``: the proxy's + answer to ``CONNECT``, and then the TLS handshake through it. The socket's timeout + was set once, on the way out of the TCP connect, and TLS would otherwise re-use + that whole value — so a proxy taking nine seconds of a ten-second deadline left the + handshake nearly ten more, and the number meant nothing again. One deadline, read + twice. + """ + super()._tunnel() + deadline = getattr(self, '_deadline', None) + if deadline is not None and self.sock is not None: + self.sock.settimeout(max(0.05, deadline - time.monotonic())) + + def stop_now(self) -> None: + """Make whatever the main thread is waiting for on this socket return, now.""" + transport = self.sock or getattr(self, '_transport', None) + if transport is not None: + transport.shutdown(socket.SHUT_RDWR) + + +def _resolve_within(host: str, port, deadline: float) -> list: + """Look the host up, and give up if the resolver does not answer in time. + + **The only thread in this program, and it is here because the standard library gives + no other way.** ``socket.getaddrinfo`` takes no timeout: it is a blocking call into + the system resolver, whose own limits come from ``/etc/resolv.conf`` and are typically + several seconds per nameserver, tried more than once. A container with a sick resolver + therefore stalls for tens of seconds inside a call that owns no socket — so a stop + cannot be acted on, and the completion receipt, which by then must not be abandoned, + cannot be written either. Handing the lookup to a thread is what turns that into a + number. + + The thread is a daemon and is never joined beyond the deadline: a stuck lookup ends + when the resolver finally answers, writing into a list nobody reads. That is a leak of + one thread on a path that is already failing, and the alternative is having no bound at + all on the phase that most often hangs. + """ + found: list = [] + failed: list = [] + + def look_up() -> None: + try: + found.extend(socket.getaddrinfo(host, port, 0, socket.SOCK_STREAM)) + except Exception as exc: # noqa: BLE001 — reported to the caller, never swallowed + failed.append(exc) + + thread = threading.Thread(target=look_up, daemon=True) + thread.start() + thread.join(max(0.0, deadline - time.monotonic())) + if found: + return found + if failed: + raise TransientError(f'the name {host!r} could not be resolved: {redact(failed[0])}') + raise TransientError( + f'the name {host!r} was still being looked up {CONNECT_DEADLINE_S:.0f}s after this ' + f'connection was started' + ) + + +def _connect_within(address, deadline: float, source_address=None) -> socket.socket: + """``socket.create_connection`` with ONE deadline over the whole thing. + + The standard library's version takes a timeout and spends it more than once: the name + lookup happens first with nothing applied to it, and then the value is set on each + address in turn, so four addresses mean four times the wait. This one resolves within + the deadline and gives every attempt only what is left of it. + + The socket handed back carries the remainder as its own timeout, which is what the TLS + handshake will then use — so the honest worst case for the whole establish phase is + the deadline plus one handshake operation, rather than a multiple of it. + """ + host, port = address + refusals: list = [] + for family, kind, proto, _canonical, sockaddr in _resolve_within(host, port, deadline): + left = deadline - time.monotonic() + if left <= 0: + break + connection = socket.socket(family, kind, proto) + try: + connection.settimeout(left) + if source_address: + connection.bind(source_address) + connection.connect(sockaddr) + except OSError as exc: + refusals.append(exc) + connection.close() + continue + connection.settimeout(max(0.05, deadline - time.monotonic())) + return connection + if refusals: + raise refusals[-1] + raise TimeoutError( + f'no address for {host!r} could be connected to within {CONNECT_DEADLINE_S:.0f}s' + ) + + +#: Cache of the stoppable subclass built for each connection class urllib hands us. +_STOPPABLE_CLASSES: dict = {} + + +def _stoppable_version_of(connection_class): + """The stoppable version of one of urllib's connection classes. + + Built by subclassing whatever urllib passed rather than by naming + ``http.client.HTTPSConnection`` here, so this file never restates the keyword + arguments urllib gives its own connection classes — those have changed between Python + versions, and a node that reimplemented them would break on the next one. + """ + made = _STOPPABLE_CLASSES.get(connection_class) + if made is None: + made = _STOPPABLE_CLASSES[connection_class] = type( + '_Stoppable' + connection_class.__name__, (_StoppableTransport, connection_class), {} + ) + return made def _on_stop(signum, _frame): + """Set the flag, abandon the transfer in flight, and return. Nothing else. + + **RECOMMENDATION, and the one place this file reads the guidance rather than quoting + it.** ``docs/AUTHORING.md`` says a signal handler sets a flag and does no work, "and + especially network work". Shutting down a socket is a single non-blocking syscall: it + starts nothing, waits for nothing and cannot block, so it is not work in the sense the + rule is about. The reason the rule gives — that the cancellation path itself crashes — + is why the flag is set FIRST and why the shutdown's failure is ignored: if it does not + work, this step is exactly as stopped as it would have been without it, and ordinary + control flow still sees the flag at its next check. Without the shutdown the flag is + the only mechanism, and a flag cannot be read by a process parked in a socket call. + Everything that DECIDES anything still happens in ordinary control flow. + """ global CANCELLED CANCELLED = True - for handle in list(_IN_FLIGHT): - with contextlib.suppress(Exception): - handle.close() + if _ABANDONABLE: + for transport in list(_IN_FLIGHT): + with contextlib.suppress(Exception): + transport.stop_now() with contextlib.suppress(Exception): sys.stderr.write(f'hello-node: stop requested (signal {signum}); finishing up\n') sys.stderr.flush() +@contextlib.contextmanager +def _within(seconds: float, what: str): + """Bound everything inside this block by ELAPSED time, network calls included. + + A socket timeout is not a deadline: it measures silence, so a peer that dribbles one + byte per window holds a transfer open indefinitely without ever being idle. The alarm + is what turns "no long silences" into "no long transfer", and it reaches a blocked + socket call the same way the stop handler does — by shutting the transport down, which + is the one thing that makes a syscall already in progress return. + + Used for the receipt, which is the transfer this step has promised not to abandon on a + stop. That promise is what makes an upper bound necessary rather than merely tidy: the + kill behind the stop arrives on its own schedule, and a step still politely waiting on + a store when it lands has written nothing and said nothing. + """ + + def _out_of_time(_signum, _frame): + for transport in list(_IN_FLIGHT): + with contextlib.suppress(Exception): + transport.stop_now() + with contextlib.suppress(Exception): + sys.stderr.write(f'hello-node: giving up on {what} after {seconds:.0f}s\n') + sys.stderr.flush() + + previous = signal.signal(signal.SIGALRM, _out_of_time) + signal.setitimer(signal.ITIMER_REAL, seconds) + try: + yield + finally: + signal.setitimer(signal.ITIMER_REAL, 0) + signal.signal(signal.SIGALRM, previous) + + class _Stopped(Exception): """Raised by ordinary control flow once the flag is seen.""" @@ -194,17 +487,6 @@ def _check_stopped() -> None: raise _Stopped('stop requested') -@contextlib.contextmanager -def _in_flight(handle): - _IN_FLIGHT.add(handle) - try: - yield handle - finally: - _IN_FLIGHT.discard(handle) - with contextlib.suppress(Exception): - handle.close() - - # --------------------------------------------------------------------- logging # Everything this program writes to stdout or stderr is captured by the runner, sent to @@ -464,7 +746,28 @@ def redirect_request(self, req, fp, code, msg, headers, newurl): ) -_OPENER = urllib.request.build_opener(_NoRedirects) +class _StoppableHandler: + """Substitute a stoppable connection for the one urllib was about to construct. + + Intercepting ``do_open`` rather than ``http_open``/``https_open`` is what keeps this + scheme-agnostic: the plain-HTTP path is what a local demo and this repository's own + conformance suite exercise, and the TLS path is what every presigned URL in production + uses, so a fix that covered only the first would be invisible where it matters. + """ + + def do_open(self, http_class, req, **kwargs): + return super().do_open(_stoppable_version_of(http_class), req, **kwargs) + + +class _StoppableHTTPHandler(_StoppableHandler, urllib.request.HTTPHandler): + pass + + +class _StoppableHTTPSHandler(_StoppableHandler, urllib.request.HTTPSHandler): + pass + + +_OPENER = urllib.request.build_opener(_NoRedirects, _StoppableHTTPHandler, _StoppableHTTPSHandler) def _open(url: str, *, what: str): @@ -472,6 +775,8 @@ def _open(url: str, *, what: str): request = urllib.request.Request(url, method='GET', headers={'User-Agent': USER_AGENT}) try: response = _OPENER.open(request, timeout=READ_TIMEOUT_S) + except _Stopped: + raise # the connection refused to start because this run was called off except urllib.error.HTTPError as exc: raise _classify(exc, _http_error_detail(exc), f'reading {what}') except urllib.error.URLError as exc: @@ -585,8 +890,13 @@ def _post_object(post: dict, key: str, source_path: str, size: int, what: str) - 'User-Agent': USER_AGENT}, ) try: - with _in_flight(body): + # ``closing`` releases the file handle the body streams from, on every path out. + # The transfer itself is abandoned through the CONNECTION, which is on the ledger + # from the moment its socket exists — before a byte of this body is sent. + with contextlib.closing(body): response = _OPENER.open(request, timeout=UPLOAD_TIMEOUT_S) + except _Stopped: + raise # the connection refused to start because this run was called off except urllib.error.HTTPError as exc: raise _classify(exc, _http_error_detail(exc), f'the upload of {what}') except urllib.error.URLError as exc: @@ -777,7 +1087,7 @@ def fetched_and_verified(creds: Credentials, index: int, scratch: str): def _stream(source: dict, name: str): if source.get('get_url'): - with _in_flight(_open(source['get_url'], what=f'input {name!r}')) as response: + with contextlib.closing(_open(source['get_url'], what=f'input {name!r}')) as response: while True: chunk = response.read(CHUNK_BYTES) if not chunk: @@ -885,6 +1195,11 @@ def process(creds: Credentials, manifest: dict, scratch: str) -> dict: metrics = {'files': len(INVENTORY), 'total_bytes': total_bytes, 'lines': total_lines} _write_result(creds, manifest, metrics, scratch) progress(1.0, 'done') + # One last look before the caller writes a receipt claiming success. A stop that + # landed during the final upload has to end this run as the cancellation it is, and + # the ordinary failure path — which writes a cancelled marker with this same + # inventory — is a better place to do that than a special case afterwards. + _check_stopped() return metrics @@ -990,7 +1305,31 @@ class of failure from "detected afterwards as a hash mismatch" into "impossible" It states its own identity — execution, attempt, generation — so the orchestrator can tell a receipt for THIS run from one a superseded copy of the job left behind. + + **From here on a stop request may not abandon anything, whatever this receipt says.** + Cutting the upload costs the run its only account of itself and saves nothing: every + object is already written and the work is over. + + That applies to a receipt claiming SUCCESS too, and this file argued the opposite for + one release. A stop landing inside a success receipt looks like it turns the document + into a lie, and the two obvious repairs — abandon that upload, or follow it with a + correction — both end in the same place: **a write that failed ambiguously may still be + accepted**, so the correction can commit first and the thing it corrected can land on + top of it. Two documents for one run have no defined winner. One document has no + problem to solve. + + So the caller decides what this receipt says BEFORE it is composed, and nothing + afterwards writes another. What that leaves is a run that finished its work and was + interrupted while reporting it, whose receipt says ``succeeded`` inside a launch the + orchestrator has recorded as cancelled — and that is not a lie the platform can act on: + the outcome is decided from the orchestrator's own journal, a marker can only ever VETO + a success and never claim one, a stopped attempt's objects are salvaged as diagnostics + rather than published, and the sentence an operator reads quotes the ``exit_code`` and + the ``error``, never the ``status``. The work really was done; the stop arrived late. """ + global _ABANDONABLE + _ABANDONABLE = False + inventoried = {entry['relpath'] for entry in INVENTORY} ports = {} for name, relpaths in PORTS.items(): @@ -1020,7 +1359,8 @@ class of failure from "detected afterwards as a hash mismatch" into "impossible" # force=True: the marker is written last, which on a long run is exactly when the # envelope this step started with is most likely to be dead. creds.get(force=True, allow_stale=True) - write_object(creds, MARKER_FILENAME, handle.name, len(payload), 'the completion marker') + with _within(RECEIPT_DEADLINE_S, 'the completion marker'): + write_object(creds, MARKER_FILENAME, handle.name, len(payload), 'the completion marker') finally: with contextlib.suppress(OSError): os.unlink(handle.name) @@ -1070,17 +1410,39 @@ def main() -> int: file=sys.stderr, flush=True) return code + # ONE receipt, decided here and not revisited. The flag is read once, before the + # document is composed, and whatever happens to the write afterwards this process + # never writes a DIFFERENT receipt to the same name. Two versions of this file + # tried to correct one receipt with another — first by abandoning the first write, + # then by letting it finish and following it with a second — and both lose the + # same way: a write that fails AMBIGUOUSLY may still be accepted (this file says so + # itself, in ``publish``), so the correction can commit first and the thing it was + # correcting can land on top of it. Sequential calls are not sequential commits. + stopped = CANCELLED + status = 'cancelled' if stopped else 'succeeded' + code = EXIT_CANCELLED if stopped else EXIT_OK try: - write_marker(creds, manifest, status='succeeded', exit_code=EXIT_OK) - except BaseException as marker_failure: - # The work is done and every object is in staging, but with no marker there is - # no inventory, so the run fails with no account of itself. Say why, in one - # line, and classify the ending rather than letting a traceback out. - print(f'hello-node: the work finished but the marker could not be written: ' + write_marker(creds, manifest, status=status, exit_code=code) + except StepError as marker_failure: + # This step's own refusal to produce a valid document — an oversized marker, a + # name it will not write. Nothing was offered to the store, so there is no + # doubt about what is there: nothing, and the run has no account of itself. + print(f'hello-node: the work finished but no valid marker could be written: ' f'{redact(marker_failure)}', file=sys.stderr, flush=True) - return EXIT_PERMANENT if isinstance(marker_failure, StepError) else EXIT_TRANSIENT + return EXIT_PERMANENT + except BaseException as marker_failure: + # Ambiguous by nature: a store can accept a body after the client that sent it + # has gone. So the receipt may be there or may not, and this process must not + # start telling a different story from the one it already wrote — the code was + # decided with the document and does not change now. If the document did not + # land, the platform refuses to publish a success it cannot inventory, which is + # the correct outcome for a step that cannot prove what it produced. + print(f'hello-node: the work finished but the {status} marker could not be confirmed ' + f'(it may or may not have been stored): {redact(marker_failure)}', + file=sys.stderr, flush=True) + return code log.info('done — %s file(s), %s bytes', metrics['files'], metrics['total_bytes']) - return EXIT_OK + return code finally: import shutil diff --git a/tests/conftest.py b/tests/conftest.py index 943a22d..30d4e96 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -37,6 +37,20 @@ REPO_ROOT = pathlib.Path(__file__).resolve().parent.parent +#: The one skip this suite tolerates. It is the verbatim citation check, which needs a +#: checkout of the orchestrator that this repository deliberately does not vendor, and it +#: says so in its own message. +TOLERATED_SKIP = 'test_every_contract_citation_quotes_the_platform_verbatim' + +#: Every other skip fails the run, and that is a deliberate reversal. Several tests here +#: are conditional by design — a marker that may legitimately be absent, a stimulus the +#: network may refuse to produce — and a conditional test that skips has NOT run: the +#: guard it provides is gone for that run. Reported only in a summary line, that is +#: invisible, and a guard that can disappear while the run stays green is the failure mode +#: this repository keeps rediscovering. So a skip is now a red run that names itself, and +#: whoever reads it decides whether the condition or the test is what needs fixing. +_skipped: list = [] + def pytest_addoption(parser): parser.addoption( @@ -150,3 +164,48 @@ def factory(**kwargs) -> Job: @pytest.fixture def sample_input() -> InputSpec: return InputSpec(relpath='data.csv', data=b'id,value\n1,alpha\n2,beta\n') + + +def pytest_runtest_logreport(report): + """Remember every skip, with the reason it gave — and never an expected failure. + + Pytest reports an EXPECTED xfail as skipped, with ``wasxfail`` set on the report. This + hook used to record those indiscriminately, which would have turned the next + ``expected_red_until_fixed`` test into a red session and broken the mechanism this + repository documents as its way of carrying a known gap. The marker is the difference + between "this did not run" and "this ran and failed on purpose". + """ + if not report.skipped or hasattr(report, 'wasxfail'): + return + reason = '' + if isinstance(report.longrepr, tuple) and len(report.longrepr) == 3: + reason = report.longrepr[2] + _skipped.append((report.nodeid, str(reason))) + + +def pytest_sessionfinish(session, exitstatus): + """Fail a run in which a guard silently did not run. + + A skipped test is not a passing test, and this suite's skips are all of the shape "the + premise for this measurement did not hold" — an optional document that was absent, a + network that refused to produce the stall a timing test needs. Any of them means the + property that test exists to protect went unmeasured, and the run said so only in a + number nobody reads. + """ + # Matched on the test's own name, not as a substring of the node id: a future test + # called ``..._verbatim_and_something_else`` would otherwise inherit the exemption and + # smuggle its skip through the one gate that exists to notice skips. + unexpected = [ + (nodeid, reason) for nodeid, reason in _skipped + if nodeid.rsplit('::', 1)[-1].split('[', 1)[0] != TOLERATED_SKIP + ] + if not unexpected: + return + session.exitstatus = 1 + print('\n' + '=' * 70) + print(f'{len(unexpected)} test(s) SKIPPED, so what they measure was not measured in this run:') + for nodeid, reason in unexpected: + print(f' {nodeid}\n {" ".join(reason.split())[:400]}') + print('Each skip names the premise that did not hold. Decide whether the premise or the') + print('test is what needs fixing — but do not read this run as evidence about the node.') + print('=' * 70) diff --git a/tests/test_cancellation.py b/tests/test_cancellation.py index 99aa222..3a7b838 100644 --- a/tests/test_cancellation.py +++ b/tests/test_cancellation.py @@ -1,29 +1,46 @@ -"""Being asked to stop, mid-transfer, with thirty seconds to say something useful. +"""Being asked to stop: what the step does next, and what it leaves behind. When a run is cancelled — by a person, by a deadline, by the runner losing its lease — -the agent calls its executor's ``stop``: SIGTERM, then SIGKILL **thirty seconds later** -(``agent/executors/docker_exec.py``: ``def stop(self, handle, timeout: float = 30.0)``). - -**What is NOT at stake, contrary to what this file used to say.** The run is recorded as -cancelled either way. ``agent/runner.py`` ``_classify`` asks whether cancellation was -requested BEFORE it looks at the exit code:: +the agent calls its executor's ``stop``: SIGTERM, then SIGKILL after a timeout +(``agent/executors/docker_exec.py``: ``def stop(self, handle: Any, timeout: float = +30.0)``). Thirty is that method's own default and every caller in today's build passes +nothing else — which makes it the interval this suite can observe, and **not** an interval +anybody is promised. Nothing guarantees any of it: a fence kills outright, a cancellation +may not be noticed until a heartbeat comes round, and the value passed to ``docker stop`` +is the agent's to choose. That is the standing statement at the top of section 7 of +``docs/PROTOCOL.md`` and every test here inherits it. + +**And the workload is never told.** Nothing in the nine injected variables, the credentials +envelope or the job description carries a stop deadline or a remaining time, and the stop +object the orchestrator composes on its heartbeat reaches the agent and stops there. So +every "deadline" a node sets for its own shutdown is a guess at a number it is not given — +best-effort by construction, and worth having only because the alternative is no bound at +all. Exposing the real one is an open platform task. + +**What is NOT at stake.** The run is recorded as cancelled either way. ``agent/runner.py`` +``_classify`` asks whether cancellation was requested BEFORE it looks at the exit code:: if context.cancel_requested.is_set() or exit_code == EXIT_CANCELLED: return 'cancelled', 'cancelled on request' so a step that ignores SIGTERM and is SIGKILLed still ends as ``cancelled``, not as a -retry. Exit code 20 and a marker saying ``exit_code: 20`` are therefore NOT required, and -the tests here no longer demand them. That was the harness inventing a rule. - -**What is genuinely at stake** is three things, none of them invisible: - -* **Thirty seconds of a runner slot, per cancelled job.** The grace period is paid in - full by a step that cannot be stopped. Cancel a batch of two hundred and that is over - an hour and a half of capacity spent on work somebody already said they did not want. -* **A receipt that contradicts the record.** The step keeps working after the stop - request and writes ``status: "succeeded"``. The launch is cancelled; the document - inside it says the step finished its work. ``_step_account`` quotes that document into - what a human reads about the run. +retry. Nothing here may demand exit 20 as a rule. What that line does say, read the other +way round, is that ``exit_code == EXIT_CANCELLED`` is the whole of the distinction when +nobody asked: a step that stops itself and says 20 is recorded as stopped, and one that +says anything else is recorded as broken. + +**What is genuinely at stake** is four things, none of them invisible: + +* **The nominal grace, per cancelled job**, paid in full by a step that cannot be + stopped. Cancel a batch of two hundred and that is over an hour and a half of capacity + spent on work somebody already said they did not want. +* **Whether the step notices at all while it is inside a transfer.** A flag cannot be + read by a process parked in a socket call, so a handler that only sets one leaves the + step's stop latency equal to its network timeouts. Measured on this file's own previous + version: **12.2 seconds**, all of it spent waiting for a response nobody needed. +* **The receipt.** Salvage publishes exactly what the marker names and nothing else, and + the marker's ``error`` and ``exit_code`` are what a human reads about the run. A stop + that leaves no receipt leaves no account and no inventory. * **Work that was explicitly cancelled being done anyway** — every remaining input fetched, copied and paid for after the request to stop. @@ -33,20 +50,30 @@ nothing does not "die on SIGTERM": the signal is dropped on the floor and the program carries on. -These tests are the slowest in the suite by design. The last one deliberately pays the -full grace period, because that thirty seconds IS the finding. +**What these tests measure, and what they cannot.** A SIGTERM delivered here models the +node's own behaviour and nothing else. It is not evidence that a stopped run delivers a +partial result: on the deadline path the terminal report is refused and the marker is +never collected, and an operator's Cancel usually arrives as a SIGKILL +(``docs/PROTOCOL.md`` section 7). The receipt is written for the runs where it IS read, +and for the day those gaps close. + +These tests are among the slowest in the suite by design. One deliberately holds a +response open past the whole nominal grace, because a store that never answers is exactly +the case in which a step's own timeouts decide whether anything gets written. """ from __future__ import annotations +import json import time import pytest from conformance import contract, docker -from conformance.fakes3 import delay_when, matching +from conformance.fakes3 import delay_when, drip_when, matching from conformance.job import InputSpec from conformance.markers import conforms_today, reference_quality +from conformance.stalling import TUNNEL_GRANTED, StallingEndpoint, a_body_that_stops #: Long enough that the signal lands squarely inside the transfer, short enough that a #: correct implementation finishes well inside the grace period. @@ -56,6 +83,41 @@ #: getting away with finishing the work it was told to abandon. HELD_PAST_THE_GRACE = docker.STOP_GRACE_SECONDS + 15.0 +#: What "promptly" means here, and the number is ours to pick rather than derived from +#: anything. ``docs/CONFORMANCE.md`` tells a node author to assert that the process exited +#: "within a few seconds" and to keep the threshold small precisely BECAUSE the thirty +#: seconds is not a promise — a node sized against the nominal grace is a node that gets +#: nothing done on a stop that gives it none. Five is a few, and it is roughly twenty +#: times what this step actually takes, so the test fails on a change of mechanism rather +#: than on a slow machine. +PROMPTLY_SECONDS = 5.0 + +#: How much of a body the stalling listener delivers, and how much it promises. The sent +#: half has to exceed any socket buffer, so its own ``sendall`` cannot finish until the +#: step has consumed nearly all of it — that is the evidence the step is inside the body +#: and not still parsing headers. The promised half has to exceed the sent half, so there +#: is always something left to wait for. +STALLED_BODY_SENT = 16 * 1024 * 1024 +STALLED_BODY_PROMISED = 64 * 1024 * 1024 + +#: The bar for the one wait nothing can interrupt — the name lookup, the TCP connect and +#: the TLS handshake, which happen inside a single call that hands out no socket to shut +#: down. A stop landing there cannot be acted on until the call returns, so what is +#: measured is that the step BOUNDS that stretch, not that it cuts it. Deliberately a +#: different number from the one above, and deliberately larger: two different mechanisms +#: must not hide behind one threshold. +#: +#: **The value is a judgement and says so.** It sits between the deadline a node should +#: give itself for reaching a store and the twenty-five seconds it allows a transfer that +#: has begun — so this fails if the establish phase stops being separately bounded and +#: falls back on the transfer timeout, which is the defect it was written for. It is +#: deliberately NOT derived from the node's own constant: a test whose bar is the thing it +#: is testing passes by construction. A node that bounded the phase at twenty seconds would +#: pass this and still be badly tuned; how generous the bound should be is argued in prose +#: in node.py, where the trade-off (a stop nobody promised you time for, against killing a +#: healthy job that no automatic retry will ever rescue) can actually be weighed. +ESTABLISH_BOUND_SECONDS = 14.0 + THREE_INPUTS = [ InputSpec(relpath='one.csv', data=b'one\n'), InputSpec(relpath='two.csv', data=b'two\n'), @@ -72,6 +134,41 @@ 'launch the orchestrator has recorded as cancelled.' ) +_THE_RECEIPT = ( + 'Nothing obliges a stopped step to write anything. pipelines/external_finalize.py salvages only ' + '"Publish what a FAILED or cancelled step managed to write. Best-effort about OBJECTS.", and it ' + 'answers an absent marker with a reported finding rather than a refusal: "No completion marker was ' + 'written, so the step gave no account of itself and nothing it produced could be salvaged." A marker ' + 'is REQUIRED only after a reported success, so on this path the contract permits silence and this ' + 'expectation may never be written down as a rule. What it is worth is measurable and large: the ' + 'marker is the only inventory salvage can publish from, and its error and exit_code are the sentence ' + 'a human reads about the run. external/contract.py describes the shape without demanding it — ' + '"A cancelled run still writes a marker: partial logs and partial outputs are exactly what someone ' + 'will want to look at afterwards."' +) + +_A_WAIT_NOTHING_CAN_INTERRUPT = ( + 'Nothing in the platform says a word about how a workload connects, so every part of this is ours: ' + 'that DNS, the TCP connect and the TLS handshake are bounded separately from a transfer, and that ' + 'the bound is small. It is reference quality with a measured reason rather than a preference — a ' + 'stop arriving during those three phases cannot be acted on at all (Python\'s ssl detaches the ' + 'plain socket while wrapping it, so shutting it down raises "Bad file descriptor" and the handshake ' + 'runs to its timeout), which makes this the only stretch of the stop path where the length of a ' + 'timeout IS the stop latency. It is also the only test here that exercises TLS at all, and ' + 'production is TLS-only.' +) + +_NOTICING_IN_TIME = ( + 'Nothing measures how long a step takes to go, and nothing ever will: the agent asks docker to stop ' + 'the container and its wait loop simply watches. So a step that spends the whole nominal grace parked ' + 'in a socket call is perfectly conformant — and useless, because no interval on any stop path is ' + 'guaranteed and a stop can arrive with no usable warning at all. This repository tells node authors ' + 'to assert the process exited "within a few seconds" for exactly that reason (docs/CONFORMANCE.md, ' + '"Testing the stop path"), so holding its own reference file to the same bar is reference quality ' + 'with a measured price: this file took 12.2s to notice a stop while its handler closed the wrong ' + 'object, and 0.2s once it shut the socket down instead.' +) + @conforms_today @reference_quality(_COOPERATIVE_SHUTDOWN) @@ -82,11 +179,16 @@ def test_a_step_stopped_during_a_download_does_not_claim_it_succeeded(make_job, Validate: the container stops well inside the grace, and whatever marker it leaves does not say ``succeeded``. - What happens today is not that the step dies without a marker — it is that nothing - happens at all. SIGTERM is dropped (see the module docstring), the download - completes, the step copies the file, writes ``result.json``, writes a marker saying - ``succeeded`` and exits 0. The run is recorded as cancelled, and the receipt inside - it says the work was finished. + The prohibited outcome, and the only one asserted here, is a receipt claiming the work + was finished inside a launch the orchestrator has recorded as cancelled. Every other + ending passes, including writing no marker at all — the test that requires one is + ``test_a_stopped_step_leaves_a_receipt_and_says_it_was_stopped``, and keeping the two + apart is what stops this one from prescribing a remedy for something it merely forbids. + + This is what an earlier version of ``node.py`` did instead, and it is worth knowing + because it is what a first version of any node does: SIGTERM was dropped, the download + completed, the file was copied, ``result.json`` was written, and a marker saying + ``succeeded`` went into a run everybody else had given up on. """ job = make_job(inputs=[sample_input]) job.endpoint.hooks.on_request.append(delay_when(matching('input', index=1), HELD_OPEN_SECONDS)) @@ -173,10 +275,11 @@ def test_a_cancelled_step_stops_taking_on_new_work(make_job): Validate: the second and third inputs are never fetched. This is the test that separates "shuts down cleanly" from "ignores the request and - happens to finish". Today the step reads and uploads all three inputs after being - told to stop — the signal changes nothing at all — and the only reason the run ends - is that it ran out of work to do. Inputs are counted as DISTINCT objects rather than - as requests, so a step that retried one of them would not accidentally satisfy this. + happens to finish". An earlier version of ``node.py`` read and uploaded all three + inputs after being told to stop — the signal changed nothing at all, and the only + reason the run ended was that it ran out of work to do. Inputs are counted as DISTINCT + objects rather than as requests, so a step that retried one of them would not + accidentally satisfy this. """ job = make_job(inputs=THREE_INPUTS) job.endpoint.hooks.on_request.append(delay_when(matching('upload', index=1), HELD_OPEN_SECONDS)) @@ -204,12 +307,17 @@ def test_a_step_that_cannot_be_stopped_costs_the_whole_grace_period(make_job, sa Action: stop the container and time it. Validate: it returns well inside the thirty seconds. - Today this takes the full thirty seconds and then the container is SIGKILLed. The - exit code that follows is 137, and this test deliberately does NOT assert anything - about it: the run is recorded as cancelled regardless, because the agent asks whether - cancellation was requested before it looks at any exit code. What is real is the - stopwatch — half a minute of a runner slot, per cancelled job, spent waiting for a + An earlier version of ``node.py`` took the full thirty and was then SIGKILLed. The + exit code that follows a kill is 137, and this test deliberately does NOT assert + anything about it: the run is recorded as cancelled regardless, because the agent asks + whether cancellation was requested before it looks at any exit code. What is real is + the stopwatch — half a minute of a runner slot, per cancelled job, spent waiting for a process that was never going to answer. + + The bar here is the nominal grace, which is the *platform's* number and the most this + can ever cost. ``test_a_stop_is_noticed_without_waiting_for_the_transfer_it_landed_in`` + asks the sharper question with a number of our own choosing, and on the read path, + where nothing but the step's own timeout was ever going to end the wait. """ job = make_job(inputs=[sample_input]) job.endpoint.hooks.on_request.append(delay_when(matching('upload', index=1), HELD_PAST_THE_GRACE)) @@ -228,6 +336,536 @@ def test_a_step_that_cannot_be_stopped_costs_the_whole_grace_period(make_job, sa ) +@conforms_today +@reference_quality(_THE_RECEIPT) +def test_a_stopped_step_leaves_a_receipt_and_says_it_was_stopped(make_job): + """The thing this suite never asked for until now: a receipt at all. + + Setup: three inputs, with the store holding the FIRST input's response open for + twelve seconds, so the signal lands inside a transfer. + Action: stop the container as soon as the request has arrived. + Validate: a completion marker is in the store, it parses, and its ``status`` is + ``cancelled``. + + **Why this is not covered by "it does not claim it succeeded".** That assertion lets + an absent marker through — deliberately, because the contract permits one — and the + consequence was measured rather than supposed: a copy of ``node.py`` that writes no + marker on the stop path passes that test, passes + ``test_a_cancelled_step_stops_taking_on_new_work``, and passes + ``test_a_step_that_cannot_be_stopped_costs_the_whole_grace_period``. Only the upload + test notices, and only because in ITS scenario an object had already landed to be + missing from the inventory; stopped before it produces anything, the step could write + nothing at all and this file had nothing to say. Prompt exit was measured; the account + of the run was not. The second is the one salvage reads — it publishes exactly what a + marker names — so a run that leaves none abandons everything it had already uploaded + and explains nothing to the operator. + + ``cancelled`` and not merely "something other than succeeded": ``failed`` would be a + receipt saying the step broke, inside a launch nobody has any reason to investigate, + and the next person to read it starts looking for a defect that was never there. + """ + job = make_job(inputs=THREE_INPUTS) + job.endpoint.hooks.on_request.append(delay_when(matching('input', index=1), HELD_OPEN_SECONDS)) + + container = job.start() + assert job.endpoint.wait_for('input', timeout=60), 'the step never started reading' + container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert job.endpoint.settle(timeout=HELD_OPEN_SECONDS + docker.STOP_GRACE_SECONDS), ( + 'the store was still handling a request when this test gave up waiting for it' + ) + uploaded = job.endpoint.keys_in_order() + assert contract.MARKER_FILENAME in uploaded, ( + f'the step was stopped and wrote no completion marker: the store holds {uploaded}. Nothing it ' + f'had produced can be salvaged (salvage publishes exactly what a marker names) and the run has ' + f'no account of itself beyond the exit code {result.exit_code}' + ) + status = job.marker()['status'] + assert status == 'cancelled', ( + f'the step was asked to stop and its receipt says {status!r}. Nothing on the platform side reads ' + f'this word — the outcome comes from the orchestrator\'s own journal, and the sentence an ' + f'operator is shown quotes the exit_code and the error, never the status — so this is a ' + f'preference, and the preference is that a document nobody has to interpret should not need ' + f'interpreting: a run that was stopped says so' + ) + + +@conforms_today +@reference_quality(_THE_RECEIPT) +def test_the_receipt_of_a_stopped_step_carries_the_code_the_process_returned(make_job): + """One run, one story about how it ended. + + Setup: as above — three inputs, the first response held open. + Action: stop the container. + Validate: the marker's ``exit_code`` is the code the process really returned, and + that code is 20. + + **The agreement is the point, and the number is what makes it useful.** A marker that + says one thing while the process says another leaves two contradictory accounts of a + single run, and the platform reads both — the exit code through the agent, the marker + through ``_step_account``. As for the number: nothing requires 20 here, because the + agent asks whether cancellation was requested before it looks at any exit code. Read + that line the other way round, though, and 20 is the whole of the distinction in the + case where nobody asked — ``if context.cancel_requested.is_set() or exit_code == + EXIT_CANCELLED`` is what separates a run recorded as stopped from one recorded as + broken when the platform has no other way to tell. + """ + job = make_job(inputs=THREE_INPUTS) + job.endpoint.hooks.on_request.append(delay_when(matching('input', index=1), HELD_OPEN_SECONDS)) + + container = job.start() + assert job.endpoint.wait_for('input', timeout=60), 'the step never started reading' + container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert job.endpoint.settle(timeout=HELD_OPEN_SECONDS + docker.STOP_GRACE_SECONDS) + if contract.MARKER_FILENAME not in job.endpoint.keys_in_order(): + pytest.skip( + 'the step wrote no marker, so there is no second account of this run to disagree with the ' + 'first — which is a legal ending, and the test above is the one that is about it' + ) + marker = job.marker() + assert marker.get('exit_code') == result.exit_code, ( + f'the receipt says the step exited {marker.get("exit_code")!r} and the process exited ' + f'{result.exit_code!r} — one run, two accounts, and the platform reads both' + ) + assert result.exit_code == contract.EXIT_CANCELLED, ( + f'the step was stopped and exited {result.exit_code}, not {contract.EXIT_CANCELLED}. Nothing ' + f'refuses that, but it is the only signal that says "stopped" rather than "broken" when the ' + f'platform was not the party that asked' + ) + + +@conforms_today +@reference_quality(_THE_RECEIPT) +def test_a_stopped_step_claims_no_object_the_store_never_received(make_job): + """The inventory has to be true in both directions. + + Setup: two inputs, with the store holding the SECOND upload open for twelve + seconds, so one object has certainly landed and one is in flight. + Action: stop the container, then wait for the store to settle. + Validate: every relpath the marker inventories names an object the store really + holds. + + The sibling test asserts the other direction — that nothing which landed is missing + from the marker — and neither implies the other. This one is about a receipt that + over-claims: an inventory naming an object nobody can find. **The platform survives + it**: salvage is "best-effort about OBJECTS" and drops one it cannot verify, keeping + the rest, so this is not a rule and no fix is prescribed. What it costs is the trust + a reader puts in the document — an inventory that has to be re-verified before it can + be believed is not an inventory, and this file is the one people copy. + + Two premises, and both are ordinary legal outcomes rather than assertions: a step may + leave no marker, and a step may account for nothing at all (having abandoned rather + than recorded what it had begun). Either way there is no claim to be false, and the + test says which happened instead of manufacturing a pass. + """ + job = make_job(inputs=THREE_INPUTS[:2]) + job.endpoint.hooks.on_request.append(delay_when(matching('upload', index=2), HELD_OPEN_SECONDS)) + + container = job.start() + assert _wait_for_upload_number(job, 2), 'the step never reached its second upload' + container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert job.endpoint.settle(timeout=HELD_OPEN_SECONDS + docker.STOP_GRACE_SECONDS), ( + 'the store was still handling a request when this test gave up waiting for it, so the objects it ' + 'holds are still changing and nothing read from it now is the state collection would see' + ) + if contract.MARKER_FILENAME not in job.endpoint.keys_in_order(): + pytest.skip('the step left no marker, so it claimed nothing and there is nothing to hold to') + inventoried = [obj['relpath'] for obj in job.marker()['objects']] + if not inventoried: + pytest.skip( + 'the step inventoried nothing — the other legal answer to being stopped mid-write, and one ' + 'that cannot over-claim' + ) + held = set(job.endpoint.keys_in_order()) + missing = [relpath for relpath in inventoried if relpath not in held] + assert not missing, ( + f'the receipt inventories {missing}, which the store never received. Salvage will try each of ' + f'them, fail to verify it and drop it, so the claim costs nothing but is still false: the store ' + f'holds {sorted(held)}' + ) + + +@conforms_today +@reference_quality(_NOTICING_IN_TIME) +def test_a_stop_is_noticed_without_waiting_for_the_transfer_it_landed_in(make_job, sample_input): + """A flag cannot be read by a process parked in a socket call. + + Setup: the store accepts the first input's request and never answers it — held + open past the whole nominal grace period. + Action: stop the container once that request has arrived, and time it. + Validate: the container is gone within a few seconds. + + **This is the assertion that separates handling a stop from having a handler.** + Installing one and then blocking in a read until it times out is not stopping; it is + finishing, slowly, for a run nobody will collect. The distinction is invisible to + every other test here, because a store that eventually answers lets a step that + waited look exactly like a step that stopped — which is why this one holds the + response open longer than the stop is nominally given. + + Measured against this file's previous version, where the handler set the flag and + closed the response object: **12.2 seconds** on a response held for twelve, and the + real bound was the 25-second socket timeout, since closing a response neither + interrupts a blocked read nor exists at all while the store is still deciding whether + to answer. + """ + job = make_job(inputs=[sample_input]) + job.endpoint.hooks.on_request.append(delay_when(matching('input', index=1), HELD_PAST_THE_GRACE)) + + container = job.start() + assert job.endpoint.wait_for('input', timeout=60), 'the step never started reading' + grace_used = container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert grace_used < PROMPTLY_SECONDS, ( + f'the step took {grace_used:.1f}s to go after being asked to stop, with a store that was never ' + f'going to answer it. Nothing refuses that — but nothing guarantees it those seconds either, so ' + f'a step that needs them is a step that writes nothing on a stop that gives it none. It exited ' + f'{result.exit_code}' + ) + + +@conforms_today +@reference_quality(_NOTICING_IN_TIME) +def test_a_stop_while_a_body_is_still_arriving_does_not_wait_for_the_rest(make_job): + """The wait after the answer has begun, which is a different object from the one before. + + Setup: the input's URL points at a listener that promises a large response, + delivers enough of it that the step is certainly reading the body, and then + goes silent for ever. + Action: let the step get past the headers and into the body, then stop the container. + Validate: it is gone within a few seconds. + + **Why this is not the same test as the one above it.** A client waiting for a store to + START answering and a client reading a body that has STOPPED arriving are two waits + reached through two different objects, and a node can be interruptible in the first and + not the second — which is exactly what this file shipped. ``http.client`` closes the + connection object as soon as it has parsed the headers of a ``Connection: close`` + response, and urllib sets that header on every request, so a ledger that forgets a + connection when it is closed is empty for the whole of the body. The fake store cannot + produce this case: its hooks run while a request is still being authorised, before a + byte of the response exists. + """ + # The pin has to allow the bytes this listener sends, or the step refuses them before + # it ever blocks and the stall never happens — measured, when a fourteen-byte pin met a + # sixteen-megabyte preamble and the run failed on "larger than the job pinned" instead. + # A synthetic pin of exactly what the response promises leaves the size check with + # nothing to complain about, and the step waits for a body that stops arriving. + with StallingEndpoint(a_body_that_stops(sent=STALLED_BODY_SENT, promised=STALLED_BODY_PROMISED)) as quiet: + job = make_job(inputs=[ + InputSpec(relpath='data.csv', synthetic_size=STALLED_BODY_PROMISED, + extra={'get_url': quiet.url(docker.HOST_ALIAS)}), + ]) + container = job.start() + # Waits for EVIDENCE, not for a moment: the listener announces only once its own + # sendall of sixteen megabytes has returned, which cannot happen until the step has + # consumed most of them. Anything weaker — announcing on accept, then sleeping — + # would let the signal land in the wait BEFORE the answer, and this test would + # quietly become a copy of its sibling while still passing. + assert quiet.wait_for_stall(timeout=60), 'the step never got into the body of its input' + grace_used = container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert grace_used < PROMPTLY_SECONDS, ( + f'the step took {grace_used:.1f}s to go while it was reading a body that had stopped arriving. ' + f'The rest of it was never coming, so that is the whole of a read timeout spent on a run already ' + f'called off. It exited {result.exit_code}' + ) + + +@conforms_today +@reference_quality(_A_WAIT_NOTHING_CAN_INTERRUPT) +def test_a_stop_during_a_tls_handshake_is_bounded_even_though_it_cannot_be_cut(make_job): + """The one wait on this path that no signal can shorten — so it has to be short. + + Setup: the input's URL is **https**, pointing at a listener that accepts the + connection and never negotiates anything. + Action: stop the container once that connection has been accepted. + Validate: it is gone in a few seconds — bounded by the step's own connect budget + rather than by the twenty-five seconds a transfer is allowed. + + **This is the only test here that does not claim promptness, and the difference is + real.** DNS, the TCP connect and the TLS handshake happen inside one call that hands + out no socket anybody else can reach: Python's ``ssl`` detaches the plain socket while + it wraps it, so shutting that down raises ``Bad file descriptor`` and the handshake + runs to its timeout regardless (measured). What cannot be interrupted has to be + bounded, and what is asserted here is that it IS bounded — separately, and tightly, + rather than inheriting the timeout meant for moving bytes. + + **It is also the only test in this suite that exercises TLS**, and that matters more + than the stall it measures: every presigned URL in production is https, this harness's + store is plain http, and a stop mechanism that had been proved only over http would be + a claim about the wrong protocol. No certificate is involved — a handshake stalls + before any certificate is offered, so refusing to speak at all is enough. + """ + with StallingEndpoint() as silent: + job = make_job(inputs=[ + InputSpec(relpath='data.csv', data=b'never arrives\n', + extra={'get_url': silent.url(docker.HOST_ALIAS, scheme='https')}), + ]) + container = job.start() + # Announced only once the listener has READ something, which for a TLS client is + # its hello: proof that negotiation has begun. Signalling on accept alone would + # leave the raw socket still owned and interruptible on an unlucky schedule, and a + # node with an unbounded handshake could then pass this for the wrong reason. + assert silent.wait_for_stall(timeout=60), 'the step never began negotiating' + grace_used = container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert grace_used < ESTABLISH_BOUND_SECONDS, ( + f'the step took {grace_used:.1f}s to go while a TLS handshake was hanging. Nothing can cut that ' + f'handshake, so the only thing standing between a stop and the end of the run is how long the ' + f'step is prepared to wait for a connection — and it should be prepared to wait for a connection ' + f'far less long than it waits for bytes. It exited {result.exit_code}' + ) + + +@conforms_today +@reference_quality(_THE_RECEIPT) +def test_a_stop_while_the_receipt_is_in_flight_leaves_exactly_one_receipt(make_job, sample_input): + """One run, one document — the rule that replaced two failed attempts at correcting one. + + Setup: one input, so the third upload is the completion marker itself, and the store + holds that upload open for twelve seconds. + Action: stop the container while its own receipt is in flight. + Validate: the store received the marker's name exactly ONCE, and the code the process + returned agrees with what that one document says. + + **Why not "the receipt must say cancelled".** Two earlier versions of this file tried + to make it say that, and both created a second write to the same key: the first + abandoned the in-flight upload and wrote a cancellation, the second let it finish and + wrote a correction afterwards. Both lose the same way — a write that fails ambiguously + may still be accepted, so the correction can commit first and the thing it corrected + can land on top of it. Sequential calls are not sequential commits, and this harness + reproduces the inversion in both directions. + + **And the state they were trying to prevent turns out not to be one the platform can + act on.** A `succeeded` receipt beside a launch the orchestrator recorded as cancelled + changes nothing there: the outcome is decided from the orchestrator's own journal + (`_TERMINAL_LAUNCH_OUTCOMES`, keyed on the launch state), a marker can only ever VETO a + success and never claim one, a stopped attempt's objects are salvaged as diagnostics + with no output port rather than published, the cascade sits behind a compare-and-set + that a cancellation loses, and the sentence an operator reads quotes the marker's + `exit_code` and `error` — never its `status`. A step that finished its work and was + interrupted while REPORTING it has genuinely succeeded; the stop arrived late. + + So what a stopped step owes here is not a particular word. It is that whatever it says, + it says once, and its exit code says the same thing. + """ + job = make_job(inputs=[sample_input]) + job.endpoint.hooks.on_request.append(delay_when(matching('upload', index=3), HELD_OPEN_SECONDS)) + + container = job.start() + assert _wait_for_upload_number(job, 3), 'the step never reached its third upload — the marker' + container.stop(grace=docker.STOP_GRACE_SECONDS) + result = container.collect() + + _assert_it_really_stopped(result) + assert job.endpoint.settle(timeout=HELD_OPEN_SECONDS + docker.STOP_GRACE_SECONDS), ( + 'the store was still handling a request when this test gave up waiting for it' + ) + written = [key for key in job.endpoint.keys_in_order() if key == contract.MARKER_FILENAME] + assert len(written) <= 1, ( + f'the step wrote {len(written)} completion markers for one run. Whichever it meant to stand, the ' + f'store decides between overlapping writes and neither the step nor S3 defines which wins — so ' + f'the run has two accounts of itself and no way to say which is current' + ) + if not written: + pytest.skip('the step wrote no receipt at all, which is legal here and is another test\'s subject') + marker = job.marker() + assert marker.get('exit_code') == result.exit_code, ( + f'the one receipt says the step exited {marker.get("exit_code")!r} and it returned ' + f'{result.exit_code!r}. One document, and it disagrees with the process that wrote it' + ) + assert (marker['status'] == 'cancelled') == (result.exit_code == contract.EXIT_CANCELLED), ( + f'the receipt says {marker["status"]!r} beside exit {result.exit_code} — the status and the code ' + f'are the same claim told twice, so they cannot differ' + ) + + +@conforms_today +@reference_quality(_THE_RECEIPT) +def test_the_receipt_is_given_a_deadline_of_its_own(make_job, sample_input): + """The one transfer this step will not abandon is the one that needs a clock. + + Setup: the store answers the receipt's upload by DRIBBLING it out — one byte at a + time over forty seconds, so it is never idle for long and a socket timeout + never fires. + Action: run the job to its end and time the container. + Validate: the step gives up inside the grace a stop is nominally given, rather than + waiting out the whole answer. + + A socket timeout measures SILENCE, not duration: a peer that sends a byte every second + is never quiet, so an inactivity timeout of ten seconds does not bound a forty-second + answer at all. That is tolerable for a transfer a stop can abandon, and not tolerable + for the receipt, which this step has promised not to abandon — the promise is exactly + what makes an upper bound necessary, because the kill behind a stop arrives on its own + schedule and a step still politely waiting on a store when it lands has written nothing + and said nothing. + + **The bar here is a judgement and not a promise**, because there is no promise to be + had: every stop path today passes the executor's own thirty-second default, but nothing + tells the workload that, and nothing tells it how much of it is left. Thirty is + therefore the most a polite stop has ever been observed to give, not a guarantee — a + fence gives none at all, and a grace can be spent before the container is even + signalled. So this threshold says only that a self-imposed save deadline must be short + enough to be worth having; it cannot say the deadline will be honoured. + """ + job = make_job(inputs=[sample_input]) + job.endpoint.hooks.on_request.append(drip_when(matching('upload', index=3), 40.0)) + + began = time.monotonic() + result = job.run(timeout=120) + elapsed = time.monotonic() - began + + assert result.exit_code is not None, 'the container had not finished' + assert elapsed < docker.STOP_GRACE_SECONDS - 2, ( + f'the step spent {elapsed:.1f}s on a receipt whose answer was dribbled out over forty. Nothing ' + f'was ever idle, so no socket timeout could end it — only an elapsed deadline can, and without ' + f'one this transfer outlives the whole grace a stop is given. It exited {result.exit_code}' + ) + + +@conforms_today +@reference_quality(_A_WAIT_NOTHING_CAN_INTERRUPT) +def test_one_connect_deadline_covers_every_address_a_name_has(make_job, image): + """A budget spent once per address is not a budget. + + Setup: the input's host is put in the container's ``/etc/hosts`` three times, on + three addresses whose packets are dropped in silence. + Action: run the job to its end and time the container. + Validate: the whole thing is over inside one establish bound, not three. + + ``socket.create_connection`` takes a timeout and applies it **separately to each + address it was given**, so a node that passes it a number is not saying what it thinks + it is saying: a host with four addresses waits four times as long. This is the shape + that hides, because the ordinary case — one address — behaves exactly as intended. + + No signal is sent here. The subject is the bound itself, which matters as much to a + step that is stopped as to one that is merely stuck: the receipt a stopped run writes + is a connection like any other, made at the moment there is least time left to make one. + """ + dead = tuple(('unanswered.invalid', address) for address in docker.SILENTLY_DROPPED) + # The premise is not "one address hangs" — it is "this name costs a MULTIPLE of the + # timeout under the implementation being guarded against", and the check has to prove + # the property it needs rather than something adjacent. Probing one address for 2s and + # accepting 1.5s did not: an address that fails at the kernel's own ~3s ARP give-up + # passes that, and three of those cost ~9s under the broken implementation — inside + # this test's own threshold, so the guard would have gone green against the very thing + # it exists to catch. + probe_timeout = 4.0 + spent = docker.seconds_spent_connecting(image, 'unanswered.invalid', timeout=probe_timeout, + extra_hosts=dead) + if spent < probe_timeout * len(dead) * 0.9: + pytest.skip( + f'reaching a name on {len(dead)} dropped addresses costs {spent:.1f}s on this machine, not ' + f'the {probe_timeout * len(dead):.0f}s a timeout spent once per address would cost, so the ' + f'network here answers rather than drops and the multiplication this test measures cannot ' + f'be produced at all' + ) + + job = make_job(inputs=[ + InputSpec(relpath='data.csv', data=b'never arrives\n', + extra={'get_url': 'http://unanswered.invalid:9/held-open'}), + ]) + began = time.monotonic() + result = job.run(timeout=120, extra_hosts=dead) + elapsed = time.monotonic() - began + + assert result.exit_code is not None, 'the container had not finished' + assert elapsed < ESTABLISH_BOUND_SECONDS + 6.0, ( + f'the step spent {elapsed:.1f}s failing to reach a host with {len(dead)} addresses. One deadline ' + f'should cover the lot; spent per address it is multiplied by however many a name happens to ' + f'have, which is not a number this node chose or can see. It exited {result.exit_code}' + ) + + +@conforms_today +@reference_quality(_A_WAIT_NOTHING_CAN_INTERRUPT) +def test_a_name_lookup_that_hangs_is_bounded_too(make_job, image): + """The phase with no socket at all — and the one a receipt cannot survive. + + Setup: a resolver of our own that receives every query and answers none, and a + container told to be patient with it. An ordinary lookup against it takes + forty seconds. The store is reached through ``/etc/hosts`` and is + unaffected; only the input's host needs resolving. + Action: run the job to its end and time the container. + Validate: it is over inside one establish bound. + + ``socket.getaddrinfo`` takes no timeout at all — it is a blocking call into the system + resolver, whose patience comes from ``/etc/resolv.conf`` and is measured in tens of + seconds. It owns no socket, so a stop cannot be acted on inside it, and the completion + receipt — which by then must not be abandoned — cannot be written either. + + **The resolver has to swallow the query rather than be unreachable**, and the first + version of this test got that wrong: an address in TEST-NET-3 fails in 0.4 s because + nothing is routed to it, so the test passed against a node with no bound at all. + """ + job = make_job(inputs=[ + InputSpec(relpath='data.csv', data=b'never arrives\n', + extra={'get_url': 'http://nowhere.invalid:9/held-open'}), + ]) + + with docker.silent_resolver(image) as resolver: + began = time.monotonic() + result = job.run(timeout=180, dns=(resolver,), dns_options=('timeout:10', 'attempts:2')) + elapsed = time.monotonic() - began + + assert result.exit_code is not None, 'the container had not finished' + assert elapsed < ESTABLISH_BOUND_SECONDS + 6.0, ( + f'the step spent {elapsed:.1f}s on a name lookup that was never going to answer. That is the ' + f"resolver's patience, not this step's: nothing in the standard library bounds a lookup, so a " + f'node that wants a number here has to impose one. It exited {result.exit_code}' + ) + + +@conforms_today +@reference_quality(_A_WAIT_NOTHING_CAN_INTERRUPT) +def test_a_proxy_does_not_get_the_connect_deadline_twice(make_job): + """Two waits inside one connect, and only one deadline to spend on them. + + Setup: the container is given an HTTPS proxy that grants the tunnel **slowly** — + seven seconds — and then never speaks again, so the TLS handshake behind it + stalls. The input is an https URL, which is what makes urllib tunnel. + Action: run the job to its end and time the container. + Validate: the whole establish phase is over inside one bound, not two. + + A proxied connect is where "one deadline" is easiest to believe and least likely to be + true: the socket's timeout is set once, on the way out of the TCP connect, and the + handshake after the tunnel re-uses that same value — so a proxy that eats most of the + budget leaves the handshake nearly all of it again. Nothing about the ordinary, + proxy-less path shows this, which is exactly why it is worth a test: it is invisible + until somebody's ``HTTPS_PROXY`` is set, and invisible again afterwards because it only + costs time. + """ + with StallingEndpoint(TUNNEL_GRANTED, answer_after=7.0) as slow_proxy: + job = make_job(inputs=[ + InputSpec(relpath='data.csv', data=b'never arrives\n', + extra={'get_url': 'https://unreachable.example/held-open'}), + ]) + + began = time.monotonic() + result = job.run(timeout=120, env={'HTTPS_PROXY': slow_proxy.url(docker.HOST_ALIAS)}) + elapsed = time.monotonic() - began + + assert result.exit_code is not None, 'the container had not finished' + assert elapsed < ESTABLISH_BOUND_SECONDS, ( + f'the step spent {elapsed:.1f}s getting a connection through a proxy that took seven of them to ' + f'answer. One deadline covers reaching the peer AND negotiating with it; read once and applied ' + f'twice it is doubled by anybody who happens to sit in between. It exited {result.exit_code}' + ) + + def _wait_for_upload_number(job, wanted: int, timeout: float = 60.0) -> bool: """Block until the store has RECEIVED its ``wanted``-th upload request. diff --git a/tests/test_harness_self.py b/tests/test_harness_self.py index 6530f08..e4f4348 100644 --- a/tests/test_harness_self.py +++ b/tests/test_harness_self.py @@ -38,6 +38,7 @@ from conformance import citations, contract, docker from conformance.fakes3 import Blob, Endpoint, delay_when, matching +from conformance.stalling import StallingEndpoint, a_body_that_stops from conformance.job import InputSpec, Job from conformance.markers import harness_self_test, our_policy, traces_to @@ -644,3 +645,73 @@ def _env_in_container(image: str, *, name: str, unset: tuple[str, ...]) -> dict[ return json.loads(result.stdout.strip().splitlines()[-1]) finally: container.remove() + + +@harness_self_test +@our_policy( + 'The stalling listener is an instrument, and this is the reading it must not get wrong. Its whole ' + 'purpose is to let a test signal a container at a moment it can otherwise only guess at, so an ' + 'announcement that arrives before the client is really waiting hands every test built on it a way to ' + 'pass for the wrong reason — a node with an unbounded handshake looks prompt if the signal lands ' + 'while the raw socket is still interruptible. Announcing on accept() is exactly that mistake, and it ' + 'is the version this harness shipped first. ' + _INSTRUMENT +) +def test_the_stalling_listener_announces_only_once_a_client_is_really_waiting(): + """Setup: two listeners — one silent, one with a preamble far larger than any buffer. + Action: connect to each without speaking, and without reading. + Validate: neither announces; the silent one announces once bytes are sent to it, and + the loud one stays quiet while its own sendall is blocked on backpressure. + + The two halves are the two waits the cancellation tests are built on. A TLS client is + "really waiting" once it has sent its hello, which is evidence the listener can read + directly. An HTTP client is "really waiting" once it is inside the body rather than the + headers, which the listener cannot see at all — but it can refuse to announce until its + own sixteen megabytes have been taken off its hands, and nothing takes them but a + client that is reading. + """ + with StallingEndpoint() as silent, StallingEndpoint(a_body_that_stops()) as loud: + quiet_client = socket.create_connection((LOCALHOST, silent.port), timeout=10) + loud_client = socket.create_connection((LOCALHOST, loud.port), timeout=10) + try: + assert silent.wait_for_stall(timeout=0.75) is False, ( + 'the silent listener announced a stall before the client had said anything, so a test ' + 'signalling on it would be signalling before TLS negotiation had begun' + ) + assert loud.wait_for_stall(timeout=0.75) is False, ( + 'the listener with a preamble announced before the client had read any of it' + ) + quiet_client.sendall(b'\x16\x03\x01\x00\x2f') # the first bytes of a ClientHello + assert silent.wait_for_stall(timeout=10), ( + 'the client spoke and the listener never noticed, so nothing can be synchronised on it' + ) + loud_client.sendall(b'GET /held-open HTTP/1.1\r\nHost: x\r\n\r\n') + assert loud.wait_for_stall(timeout=0.75) is False, ( + 'the listener announced while its own sendall was still blocked, which means it was not ' + 'waiting for the client to consume anything and the mid-body test is synchronised on ' + 'nothing' + ) + # Drain until the listener lets go, rather than until some fixed number of + # bytes: how much has to be taken before ``sendall`` can finish depends on the + # socket buffers, which are the machine's business and not this test's. A first + # version drained eight megabytes and called that enough — true where the + # buffers are large, false on CI, and a test that passes on the author's + # machine and fails on the runner is a test that measured the machine. + drained = 0 + preamble = len(a_body_that_stops()) + while drained < preamble and not loud.wait_for_stall(timeout=0.05): + drained += len(loud_client.recv(1024 * 1024)) + assert loud.wait_for_stall(timeout=20), ( + f'the client drained {drained} of {preamble} bytes and the listener still never ' + f'announced, so nothing can be synchronised on it' + ) + # A client that goes away without asking for anything must NOT be announced as + # a stall: an instrument that reports somebody waiting when nobody is sends a + # test's signal into an empty room and calls whatever happens a pass. + with StallingEndpoint() as abandoned: + socket.create_connection((LOCALHOST, abandoned.port), timeout=10).close() + assert abandoned.wait_for_stall(timeout=1.5) is False, ( + 'a client that connected and closed without speaking was announced as a stall' + ) + finally: + quiet_client.close() + loud_client.close() diff --git a/verify_mutations.py b/verify_mutations.py new file mode 100644 index 0000000..1db1980 --- /dev/null +++ b/verify_mutations.py @@ -0,0 +1,157 @@ +"""Re-run every mutation `CONFORMANCE-BASELINE.md` claims, against the suite as it stands. + +For each: patch the file, run the named test(s), record the outcome and the assertion +message, restore. A claim survives only if the named test FAILS under its mutation, and +the script exits non-zero if any does not. + +**This exists because the document once claimed three guards that were not in the suite.** +The mutations behind them had really been run — and then an edit that replaced a slice of +the test file between two anchors deleted the tests, leaving the claims behind. Nothing +noticed, because a claim about a test is prose and prose is not executable. This makes it +executable: `python verify_mutations.py` from the repository root, and every row of every +mutation table in the baseline has to be a line in `MUTATIONS` below. + +Two rules learned from its own first run: + +* **Patch the path the behaviour would really take.** The "correct the receipt with a + second document" mutation was first written against the success path, where in that + scenario the first write has already timed out — so the mutation never executed and + reported a green that said nothing about the guard. +* **A green here is a finding**, not a nuisance: either the guard is gone, the mutation is + misplaced, or the claim was never true. All three have happened. +""" +import pathlib +import re +import subprocess +import sys + +REPO = pathlib.Path(__file__).resolve().parent +PYTEST = [str(REPO / '.venv-harness/bin/python'), '-m', 'pytest', '-q', '--no-header', '-p', 'no:cacheprovider'] + +MUTATIONS = [ + ('handler never installed', 'node.py', + " signal.signal(signal.SIGTERM, _on_stop)\n", + " pass # MUTATION\n", + 'leaves_a_receipt or noticed_without_waiting'), + + ('shutdown() put back to close()', 'node.py', + " transport.shutdown(socket.SHUT_RDWR)", + " transport.close() # MUTATION", + 'noticed_without_waiting'), + + ('the marker claims a file never written', 'node.py', + " sources = creds.get().get('inputs') or []\n taken: set = set()", + " sources = creds.get().get('inputs') or []\n record('outputs/ghost.csv', '0' * 64, 1, OUTPUT_PORT) # MUTATION\n taken: set = set()", + 'claims_no_object'), + + ('no marker on the stop path', 'node.py', + " global _ABANDONABLE\n _ABANDONABLE = False\n", + " global _ABANDONABLE\n _ABANDONABLE = False\n if status == 'cancelled':\n return # MUTATION\n", + 'leaves_a_receipt'), + + ('the ledger forgets a will_close connection', 'node.py', + " def stop_now(self) -> None:", + " def close(self): # MUTATION\n if self in _IN_FLIGHT:\n _IN_FLIGHT.remove(self)\n super().close()\n\n def stop_now(self) -> None:", + 'body_is_still_arriving'), + + ('one elapsed deadline replaced by per-address spend', 'node.py', + " self._create_connection = lambda address, timeout, source=None: _connect_within(\n address, self._deadline, source\n )", + " self._create_connection = lambda address, timeout, source=None: socket.create_connection(\n address, CONNECT_DEADLINE_S, source) # MUTATION", + 'every_address_a_name_has'), + + ('the name lookup left unbounded', 'node.py', + " thread = threading.Thread(target=look_up, daemon=True)\n thread.start()\n thread.join(max(0.0, deadline - time.monotonic()))", + " look_up() # MUTATION", + 'name_lookup_that_hangs'), + + ('the deadline not recomputed after a proxy CONNECT', 'node.py', + " super()._tunnel()\n deadline = getattr(self, '_deadline', None)", + " super()._tunnel()\n deadline = None # MUTATION\n _unused = getattr(self, '_deadline', None)", + 'proxy_does_not_get'), + + # Placed on the path a correction would really take: in this scenario the first write + # TIMES OUT, so a mutation on the success path alone never executes and reports a + # green that says nothing. That is what the first run of this verifier did. + ('the receipt corrected by a second document', 'node.py', + " f'(it may or may not have been stored): {redact(marker_failure)}',\n" + " file=sys.stderr, flush=True)\n return code", + " f'(it may or may not have been stored): {redact(marker_failure)}',\n" + " file=sys.stderr, flush=True)\n" + " if CANCELLED and status != 'cancelled': # MUTATION\n" + " with contextlib.suppress(Exception):\n" + " write_marker(creds, manifest, status='cancelled', exit_code=EXIT_CANCELLED,\n" + " error='stopped while the receipt was in flight')\n" + " return EXIT_CANCELLED\n" + " return code", + 'exactly_one_receipt'), + + ('the exit code revised after the document was written', 'node.py', + " print(f'hello-node: the work finished but the {status} marker could not be confirmed '\n" + " f'(it may or may not have been stored): {redact(marker_failure)}',\n" + " file=sys.stderr, flush=True)\n return code", + " print(f'hello-node: the work finished but the {status} marker could not be confirmed '\n" + " f'(it may or may not have been stored): {redact(marker_failure)}',\n" + " file=sys.stderr, flush=True)\n return EXIT_TRANSIENT # MUTATION", + 'exactly_one_receipt'), + + ("the receipt's elapsed deadline removed", 'node.py', + " with _within(RECEIPT_DEADLINE_S, 'the completion marker'):\n write_object(", + " if True: # MUTATION\n write_object(", + 'deadline_of_its_own'), + + ('the listener announces on accept()', 'conformance/stalling.py', + " with self._lock:\n self.accepted.append(connection)", + " with self._lock:\n self.accepted.append(connection)\n self._connected.set() # MUTATION", + 'stalling_listener'), +] + + +def run(selector: str) -> tuple[bool, str]: + done = subprocess.run(PYTEST + ['-k', selector], capture_output=True, text=True, cwd=REPO) + failed = ' failed' in (done.stdout + done.stderr) + message = '' + for line in done.stdout.splitlines(): + if line.startswith('E AssertionError') or line.startswith('E AssertionError'): + message = re.sub(r'\s+', ' ', line.split('AssertionError:', 1)[-1]).strip()[:150] + break + return failed, message + + +def main() -> int: + target_files = {name for _, name, _, _, _ in MUTATIONS} + backups = {name: (REPO / name).read_text() for name in target_files} + results = [] + try: + for label, filename, old, new, selector in MUTATIONS: + path = REPO / filename + source = backups[filename] + # A target that appears twice is refused rather than resolved to the first + # one. This exact hazard produced a meaningless green here: the "correct the + # receipt with a second document" patch matched both the work-failure branch + # and the receipt branch, landed in the first, and its condition was dead + # there — so the battery reported a guard as unsupported when the guard was + # fine and the mutation had gone somewhere harmless. + found = source.count(old) + if found != 1: + problem = 'PATCH TARGET MISSING' if found == 0 else f'PATCH TARGET AMBIGUOUS ({found}x)' + results.append((label, selector, problem, '')) + print(f'!! {label}: {problem}', flush=True) + continue + path.write_text(source.replace(old, new, 1)) + reds, message = run(selector) + path.write_text(source) + results.append((label, selector, 'RED' if reds else 'GREEN — CLAIM UNSUPPORTED', message)) + print(f'{"RED " if reds else "GREEN"} {label}\n {message}', flush=True) + finally: + for name, text in backups.items(): + (REPO / name).write_text(text) + unsupported = [row for row in results if row[2] != 'RED'] + print('\n' + '=' * 72) + print(f'{len(results) - len(unsupported)}/{len(results)} claims verified red against the current suite') + for label, selector, status, _ in unsupported: + print(f' UNSUPPORTED: {label} ({selector}) -> {status}') + return 1 if unsupported else 0 + + +if __name__ == '__main__': + sys.exit(main())