The flaky test was right: a 58%-reproducible race in a scroll-reading pipeline's disk cache

작성자

카테고리:

← 피드로
DEV Community · acejayl · 2026-08-22 개발(SW)

This is a submission for DEV’s Summer Bug Smash: Clear the Lineup powered by Sentry.

Project Overview

The Vesuvius Challenge uses machine learning to read carbonized Herculaneum scrolls — 2,000-year-old papyrus that was buried by the eruption of Vesuvius and can never be physically unrolled. Its open-source monorepo, ScrollPrize/villa, contains the vesuvius Python package that researchers use to stream multi-terabyte CT scan volumes and train ink-detection models.

I was setting up that package on my Windows 11 machine (the project’s CI only tests Ubuntu — the workflow file literally says “Extend this list once the build scripts for macOS and Windows are confirmed”), working with an AI coding assistant to run the test suite on a platform it had never been tested on. One test failed. Then it passed. Then it failed again.

Bug Fix or Performance Improvement

The test — test_shared_cache_multiprocess_reads_are_not_torn — spawns four processes that read one scroll volume through a shared on-disk chunk cache. Run it once and you might see nothing wrong. So I ran it twelve times: 7 failures out of 12, all PermissionError: [WinError 5] Access is denied.

A 58% flake is not a flake. It’s a bug with a coin flip attached.

The cache is on the hot path for real usage: it’s the component behind the package’s documented volume_cache_dir config and the --cache-dir flag of its inference CLI. Any PyTorch DataLoader with num_workers > 0 puts multiple processes into exactly this concurrent pattern. On Windows, training runs would randomly die mid-epoch.

Digging in (a standalone reproducer that propagated full worker tracebacks instead of repr(exc)), the failure turned out to have three separate surfaces, each hiding behind the previous one:

  1. Cache-entry commit. The zarr library commits each cache entry with a write-temp-then-os.replace pattern. On POSIX, rename(2) over a file another process has open is legal. On Windows, MoveFileEx(MOVEFILE_REPLACE_EXISTING) returns ERROR_ACCESS_DENIED. Four workers populating the same content-addressed keys collide constantly. (This is upstream zarr-developers/zarr-python#3522 — open since October, three confirmations, no fix.)
  2. Cache read. Fix the write path and a second surface appears: a concurrent commit can deny the reader’s open, too.
  3. Eviction accounting. The package’s own LRU sweep caught only FileNotFoundError when deleting old entries. Windows raises PermissionError for in-use files — and the sweep then subtracted the file’s bytes from the size budget anyway, under-evicting a cache whose entire job is staying under a byte budget. This one is a genuine bug on every operating system, not just Windows.

The fix follows one principle: a cache is an optimization, never a source of truth, so a refused cache operation must never abort the read that triggered it. I wrapped only the cache-side store: refused writes degrade to no-ops (logged at debug), unreadable entries report as a miss — which extends the store’s own existing “missing file = miss” semantics, so the outer cache simply refetches from the source. The eviction sweep now skips undeletable entries without crediting their bytes and evicts the next-oldest instead. No platform-specific branches anywhere; the trade-off (a full disk becomes slow refetches rather than a crash) is deliberate and documented.

Measured result: 58% failure → 0 failures in 12 consecutive runs. The package’s Windows test suite went from 47 passed / 2 failed to 52 passed / 0 failed.

Because a 58% race is a terrible CI signal, I also added three deterministic regression tests that force each PermissionError surface via monkeypatching instead of racing for it — each verified to fail against the unfixed code on any OS. (Plus a bonus find while in there: the LRU test stamped files with 1–3 nanosecond timestamps, which NTFS — 100 ns resolution — collapses to st_mtime_ns == 0, silently destroying the ordering the test depends on. ext4 has 1 ns resolution, which is why Linux CI never noticed.)

Code

The full fix, tests, and methodology:
https://github.com/ScrollPrize/villa/pull/1545

Three files: the cache wrapper + eviction fix in vesuvius/src/vesuvius/ink_detection/volume_io.py, the regression tests in vesuvius/tests/ink_detection/test_volume_io.py, and a platform marker in pyproject.toml (the CUDA-only cucim-cu13 dependency ships manylinux wheels only, which made uv sync --extra all unresolvable on Windows and macOS).

My Improvements

  • A component that crashed 58% of the time under multiprocess access on Windows now runs clean, on the hot path used by anyone training ink-detection models with DataLoader workers and a disk cache.
  • An OS-independent eviction accounting bug is gone.
  • CI gets a deterministic signal for a whole class of failure it previously couldn’t see — the racing test only catches the bug half the time even on the affected platform.
  • The diagnosis is documented down to the Win32 semantics, including what the upstream zarr issue was missing (mechanism, failure rate, minimal repro), so it’s actionable beyond this one repo.

Two lessons I’m keeping: run flaky tests twelve times, not twice — a 58% failure rate read as “flaky” for months because nobody measured it; and fix one surface at a time, because two of the three bugs here were invisible until the one in front of them was gone.

Workflow transparency: I did this with an AI coding assistant (Claude) driving the investigation under my direction — measuring the failure rate, bisecting the three surfaces, and drafting the fix — with every measurement re-run and verified on my machine. The villa project explicitly welcomes LLM-assisted contributions with human commentary, and this writeup plus the PR discussion is exactly that.

Best Use of Sentry

A multiprocess race condition is the hardest kind of bug to see: the failure lives in the timing overlap between separate OS processes, so a single-process debugger or a stack trace from one worker tells you almost nothing. I used Sentry to make this one visible — and to prove the fix.

Error Monitoring — capturing the race with context. I instrumented the four cache-reader processes so each captures its PermissionError to Sentry with the details that actually matter: the worker PID, the shared cache directory, and which of the three failure surfaces it hit (the os.replace commit vs. a concurrent open). Instead of a bare WinError 5, each issue carries the full concurrent context, and Sentry groups the four near-simultaneous failures into one issue — immediately showing this is a collision, not four independent flukes.

Distributed Tracing — making the invisible collision visible. This is the part a debugger can’t do. I propagated one trace across all four worker processes (Sentry’s continue_trace / trace-header propagation), with spans on each cache open and read. In the trace view, the four processes line up on a single timeline and you can see them overlapping on the exact same content-addressed cache key at the same instant — which is precisely the window where zarr’s write-temp-then-os.replace commit collides on Windows. The trace turns an abstract “race condition” into a picture of four spans stacking on one resource.

Before / after, in the same dashboard. I ran the identical workload two ways, tagged as two Sentry environments:

  • villa-cache-unfixed — captured PermissionError issues, and a trace where the four workers produced only 21 cache.read spans between them: several died mid-read the instant the race fired.
  • villa-cache-fixed — the same four workers hitting the same collision window, but the hardened cache degrades a refused write to a miss instead of raising. Zero issues, and 48 cache.read spans — every worker completed every read.

Same race window, same span instrumentation: errors and truncated traces on one environment, silence and complete traces on the other. That contrast is the proof the fix works.

The one trick that makes the cross-process trace work is propagating the parent’s trace headers into each spawned worker, then continuing that trace inside the worker:

# parent: start one trace, hand its headers to every worker process
with sentry_sdk.start_transaction(op="cache", name="cache_race_demo"):
    headers = dict(sentry_sdk.get_current_scope().iter_trace_propagation_headers())
    for _ in range(4):
        ctx.Process(target=worker, args=(..., headers)).start()

# worker: continue the SAME trace, so all four line up in one trace view
with sentry_sdk.continue_trace(headers):
    with sentry_sdk.start_transaction(op="cache", name="cache_worker_read") as tx:
        tx.set_tag("worker_pid", os.getpid())
        with sentry_sdk.start_span(op="cache.open", name="open_volume(cache)"):
            volume = open_volume(source, 0, cache_dir=cache_dir)
        ...  # cache.read spans; on PermissionError -> set_context(...) + capture_exception()

Enter fullscreen mode Exit fullscreen mode

Tooling used: Sentry Error Monitoring (contextual exception capture + issue grouping) and Distributed Tracing (cross-process trace propagation with cache spans), via a standalone reproduction harness that runs the identical four-worker workload against the unfixed and fixed cache and reports both to Sentry.

Same race window, same span instrumentation: errors and truncated traces on one environment, silence and complete traces on the other. That contrast is the proof the fix works.

The one trick that makes the cross-process trace work is propagating the parent’s trace headers into each spawned worker, then continuing that trace inside the worker:

# parent: start one trace, hand its headers to every worker process
with sentry_sdk.start_transaction(op="cache", name="cache_race_demo"):
    headers = dict(sentry_sdk.get_current_scope().iter_trace_propagation_headers())
    for _ in range(4):
        ctx.Process(target=worker, args=(..., headers)).start()

# worker: continue the SAME trace, so all four line up in one trace view
with sentry_sdk.continue_trace(headers):
    with sentry_sdk.start_transaction(op="cache", name="cache_worker_read") as tx:
        tx.set_tag("worker_pid", os.getpid())
        with sentry_sdk.start_span(op="cache.open", name="open_volume(cache)"):
            volume = open_volume(source, 0, cache_dir=cache_dir)
        ...  # cache.read spans; on PermissionError -> set_context(...) + capture_exception()

Enter fullscreen mode Exit fullscreen mode

Tooling used: Sentry Error Monitoring (contextual exception capture + issue grouping) and Distributed Tracing (cross-process trace propagation with cache spans), via a standalone reproduction harness that runs the identical four-worker workload against the unfixed and fixed cache and reports both to Sentry.

원문에서 계속 ↗