Skip to content

Let a run outlive the request that asked for it - #64

Open
jorgeMFS wants to merge 5 commits into
auth-providerfrom
async-runs
Open

jorgeMFS wants to merge 5 commits into
auth-providerfrom
async-runs

Conversation

@jorgeMFS

Copy link
Copy Markdown
Contributor

Closes #5 (B1), given the chain below lands first. Unblocks #6 (per-step logs), #7 (cancellation) and #8 (progress), which all name it as their dependency.

Merge order

Stacked. Base this on auth-provider (#63).

#48 → #45 → #46 → #57 → #58 → #59 → #62 → #63 → this

What was true before

/convert held the connection for the whole run — up to fifteen minutes by default — sending nothing until the end. A dropped connection lost the work entirely, because nothing survived the request, and a run had no identity to refer to afterwards.

It is also precisely wrong for what this service is for: dispatching a step to an HPC queue means waiting for a scheduler, not a subprocess, and there is no version of that which fits inside one HTTP request.

What it does now

POST /runs answers 202 immediately with a run_id. GET /runs/{run_id} reports state, and carries outputs once COMPLETE.

/convert is untouched — it is the contract the editor speaks today. Both now call the same perform_run rather than two copies that would drift.

States are GA4GH WES's vocabulary verbatim, so exposing this as WES (F5) is an adapter, not a rewrite.

The state machine is explicit

The transition table is written out rather than left implicit, because the interesting bugs in a state machine are the transitions nobody thought about. A terminal state has no successors at all, and an illegal move is refused rather than tolerated — a run allowed to go EXECUTOR_ERROR → COMPLETE would claim something untrue about itself, and a client would go looking for outputs that were never produced.

Which error state gets used is a real distinction:

cause state
tool exits non-zero, bad workflow, missing input EXECUTOR_ERROR — attributable to what was submitted
anything else SYSTEM_ERROR — our defect, not the workflow's fault

The store is bounded

It only ever grew otherwise, so a long-lived service would use memory in proportion to its uptime. The oldest finished run is forgotten first; a run still in flight is never evicted, because forgetting it would lose the only handle to work that is still happening.

Stated plainly rather than discovered later: runs are in memory, so nothing survives a restart and nothing is shared between replicas. That is why a persistent store is its own piece of work.

The spec is committed and cannot drift

openapi.json is generated from the service (python ci/export_openapi.py) and a test asserts the committed file matches what the app serves — so a route added without regenerating fails CI rather than shipping a document that lies. Clients are generated from it, so a stale spec is worse than none.

Thirteen mutations, no survivors — after two that did

illegal transitions allowed        illegal_transition_is_refused
terminal states get successors     terminal_state_has_no_successors
store unbounded again              store_is_bounded_and_forgets_finished_first
in-flight runs evicted             a_run_still_in_flight_is_never_forgotten
failure recorded as COMPLETE       failing_run_reaches_EXECUTOR_ERROR
system errors blamed on workflow   defect_is_SYSTEM_ERROR_not_the_workflows_fault
submit waits instead of queueing   submitting_answers_immediately
unknown run is 200                 an_unknown_run_is_404_not_500
outputs leak into a live run       run_reaches_COMPLETE_and_carries_its_outputs
openapi not regenerated            committed_openapi_document_is_current
route added, spec not regenerated  committed_openapi_document_is_current

The first survivor was my own instrument failure, and worth stating: the OpenAPI tests did not exist. I rewrote the test file wholesale — which dropped that section — then "added them back" with a str.replace whose anchor no longer matched, without asserting it. The spec was committed with nothing checking it, and only the mutation noticed.

The second was a dead include_outputs parameter no caller ever passed as False. A dead parameter guarding a security-shaped property reads like a control and is not one, so it is gone.

158 tests pass.

B1 (#5) asks two things to verify first: is the REST API synchronous, and what
happens to the HTTP connection during a long run. Yes, and it waits.

/convert does the whole job inside one request -- creates the workspace, pulls
the tools, writes the Snakefile, runs snakemake to completion, reads the outputs
back, base64-encodes them, and only then replies. BIOCHEF_RUN_TIMEOUT defaults to
900 seconds, so one request can legitimately hold a socket for fifteen minutes
and send nothing until the end.

Recorded before changing anything:

  the run happens in the request   run_in_threadpool(run_snakemake) is awaited,
                                   and the outputs are encoded after it
  the timeout is 900s              which is how long a connection may be held
  there is no second endpoint      nothing under /runs exists
  a run has no identity or state   no run_id, no RunState, none of the WES
                                   vocabulary anywhere
  no OpenAPI document is shipped   FastAPI serves one, but nothing is committed,
                                   so there is no artifact to review or diff

What it costs: the client must wait with no way to reconnect and no way to ask
how far along it is; a dropped connection loses the work entirely; and a run has
nothing to refer to afterwards, which is why cancellation (#7), per-step logs
(#6) and progress (#8) all name this as their dependency.

It is also precisely wrong for what this service is for. Dispatching a step to an
HPC queue means waiting for a scheduler rather than for a subprocess, and there
is no version of that which fits inside one HTTP request.

Refs #5
B1 (#5). /convert held the connection for the whole run -- up to fifteen minutes
by default -- and a dropped connection lost the work, because nothing survived
the request. That is also precisely wrong for what this service is for:
dispatching a step to an HPC queue means waiting for a scheduler, and there is
no version of that which fits inside one HTTP request.

POST /runs answers 202 immediately with a run_id. GET /runs/{run_id} reports the
state and carries the outputs once COMPLETE. /convert is untouched, because it is
the contract the editor speaks today; both now call the same perform_run rather
than two copies that would drift.

The states are GA4GH WES's vocabulary verbatim, spelled the same way, so that
exposing this as a WES endpoint (F5) is an adapter and not a rewrite.

The transition table is written out rather than left implicit, because the
interesting bugs in a state machine are the transitions nobody thought about. A
terminal state has no successors at all, and an illegal move is refused rather
than tolerated: a run allowed to go from EXECUTOR_ERROR to COMPLETE would claim
something untrue about itself, and a client would go looking for outputs that
were never produced.

Which error state is used is a real distinction, not a formality. A tool exiting
non-zero, a bad workflow, a missing input -- attributable to what was submitted,
so EXECUTOR_ERROR. Anything else is a defect in this service, so SYSTEM_ERROR
rather than blaming the workflow for our bug.

The store is bounded. It only ever grew otherwise, so a long-lived service would
use memory in proportion to its uptime. The oldest FINISHED run is forgotten
first, and a run still in flight is never evicted -- forgetting one would lose
the only handle to work that is still happening.

openapi.json is committed and generated from the service itself, with a test
that the committed file matches what the app serves. A route added without
regenerating fails CI rather than shipping a document that lies, which matters
because clients are generated from it.

Thirteen mutations, no survivors -- after two that initially survived, both of
which were real:

  illegal transitions allowed        illegal_transition_is_refused
  terminal states get successors     terminal_state_has_no_successors
  store unbounded again              store_is_bounded_and_forgets_finished_first
  in-flight runs evicted             a_run_still_in_flight_is_never_forgotten
  failure recorded as COMPLETE       failing_run_reaches_EXECUTOR_ERROR
  system errors blamed on workflow   defect_is_SYSTEM_ERROR_not_the_workflows_fault
  submit waits instead of queueing   submitting_answers_immediately
  unknown run is 200                 an_unknown_run_is_404_not_500
  outputs leak into a live run       run_reaches_COMPLETE_and_carries_its_outputs
  openapi not regenerated            committed_openapi_document_is_current
  route added, spec not regenerated  committed_openapi_document_is_current

The first survivor was my own instrument failure and worth recording. The
OpenAPI tests did not exist: I rewrote the test file wholesale, which dropped
that section, and then "added them back" with a str.replace whose anchor no
longer matched -- without asserting it. The spec was committed with nothing
checking it, and the mutation is what noticed.

The second was a dead include_outputs parameter no caller ever passed as False.
A dead parameter guarding a security-shaped property reads like a control and is
not one, so it is gone; outputs are only ever set on COMPLETE.

Refs #5
Auditing the previous commit found three defects, all of which only appear once
concurrency is reachable -- which is exactly what asynchronous runs made it.

Concurrent runs destroyed each other's work. Every run pulled a tool into the
same fixed ".part" directory beside the cache, and two runs would both rmtree
it, both makedirs it, and then one would os.replace a directory the other had
already moved. Twenty simultaneous submissions:

  before   COMPLETE 1, SYSTEM_ERROR 19
  after    COMPLETE 20

  [Errno 17] File exists: .../cache/tool.part
  [Errno  2] No such file or directory: .../cache/tool.part

The fix is a per-tool lock plus a staging name unique to each attempt. The lock
alone would do for one process; the unique name also survives a second process
sharing the cache directory, which is a supported deployment. Inside the lock
the cache is re-checked, because another run may have pulled the same tool while
this one waited. The race predates asynchronous runs -- two concurrent /convert
calls could always hit it -- but nothing made it easy to reach until now.

Nothing kept a reference to the background task. asyncio.create_task returns a
task the caller is expected to hold; the event loop keeps only a weak one, and a
task nobody refers to can be collected part-way through. Here that would stop
the run, leave it non-terminal, and have a client poll forever for an answer
that was never coming. Held now, and dropped when it finishes, because held
forever is a leak.

Nothing bounded how many runs execute at once. run_in_threadpool draws on
anyio's default limiter of 40, so a burst of submissions became up to forty
snakemake processes on a machine sized for rather fewer. BIOCHEF_MAX_CONCURRENT_RUNS
defaults to 4, and runs beyond it wait in QUEUED -- which is precisely what WES
means by that state, so nothing new had to be invented to express it.

Nine mutations, no survivors, after three rounds of finding my own harness at
fault:

  staging name fixed again        bundle_pulled_and_staged_first, leftover_discarded
  per-tool lock removed           many_runs_submitted_at_once, execution_is_bounded
  no re-check inside the lock     cached_bundle_not_pulled_again, second_node
  staging kept after a failure    a_failed_pull_takes_its_staging_directory_with_it
  task reference not held         background_task_is_referenced_until_it_finishes
  concurrency unbounded           execution_is_bounded_and_the_rest_wait_in_QUEUED
  limit raised to 40              default_limit_is_well_below_the_threadpool_size

Two of those needed the tests written for them. "staging kept after a failure"
was reported as a survivor twice before it was really tested -- the first anchor
did not match and the harness said so, which is the only reason it was not
recorded as passing.

One existing test had to be corrected rather than kept. It asserted that a
leftover staging directory is discarded, and gave "the reason for rmtree before
makedirs" as its rationale -- but the fixed name that rmtree cleaned is exactly
what caused the race, and with unique names a leftover is not reused because
nothing looks at it again. Same property, different reason, and the docstring
now says which.

Refs #5
Found auditing the fix from the previous commit. asyncio locks bind themselves
to an event loop the first time a waiter is created, so one module-level
Semaphore worked exactly until it was contended, and refused every later loop
after that:

  loop 1 with contention: ok
  loop 2 with contention: RuntimeError: <Semaphore [locked]> is bound to a
                          different event loop

A server runs one loop, so this would not have bitten in production. It would
have bitten in the tests, which build a fresh loop per TestClient -- and did not
only because the test that forces contention substituted a semaphore of its own.
A bound that breaks the moment someone tests it properly is not much of a bound,
and a test that avoids the shared object is not testing the shared object.

The semaphore is now created per running loop, weakly keyed so a finished loop
takes its own with it. The concurrency test patches MAX_CONCURRENT_RUNS instead
of substituting a semaphore, which is what let this hide, and a second test runs
contended workloads through two separate loops.

Verified against the defect: restoring a single shared semaphore fails
test_execution_is_bounded_and_the_rest_wait_in_QUEUED.
The post-fix audit found that a comment I had written was false. It said the
unique staging name "also survives a second process sharing the cache
directory, which is a supported deployment". It does not: _fetch_lock is a
threading.Lock and reaches only this process, and the promote is two syscalls --
rmtree then os.replace -- which is not atomic across processes. Asserting the
opposite is worse than saying nothing, because it tells the next reader not to
look.

Measured with six processes on one cold cache: two failed in every trial with
ENOTEMPTY, because os.replace will not overwrite a non-empty directory and each
had just rmtree'd it for the other.

Losing that footrace is not a failure. Whoever won had passed
verify_against_manifest against the same manifest, so their copy is as good as
ours: _promote now checks what is in place and uses it. Retried, because the
re-check races too -- a third process can rmtree between the clash and the look,
which left about one failure in twenty-four.

That exposed the other half, which the audit also named: the cache is read with
no lock at all, so a promote can delete the bundle out from under a reader.
Within a process the read now happens inside the lock. Across processes nothing
can, so fetch_tool retries a read that lands in the gap -- the state is
self-healing, since whatever the other process was putting there arrives a
moment later, verified.

  before any fix        12 failures / 24 processes
  after the lock         2 failures / 48
  after this             0 / 30, across five consecutive runs

None of that is atomicity. A directory cannot be swapped atomically on POSIX;
doing this properly means an indirection that can be, which changes the on-disk
layout and is its own piece of work. The comment now says what is true instead
of what would be convenient.

Six mutations, no survivors:

  promote does not tolerate a clash   separate_processes_sharing_a_cache
  promote tries only once             separate_processes_sharing_a_cache
  no retry on a transient miss        separate_processes_sharing_a_cache
  bundle read outside the lock        bundle_is_read_while_the_lock_is_held
  per-tool lock removed               many_threads_racing_a_cold_cache
  unique staging name reverted        bundle_pulled_and_staged_first

Two tests had to be repaired rather than kept, both mine. The lock test compared
string offsets, so dedenting the read out of the with-block left it passing
while the race was wide open; it now checks scope with ast. And the ordering
test matched "os.replace" against a COMMENT explaining the promote -- the second
time in this suite a check has been fooled by prose sitting beside the code it
describes.

Refs #5 #9
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant