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())