On Windows, four processes appending to one file lost 37 of 200 lines

My CI failed with this, only on the Windows runner, on a commit that changed nothing but a few GIFs:

receipts: Unexpected token '\', "\hostedtoo"... is not valid JSON

The same test had passed on that runner a few hours earlier. Here is what it was, because it is a small bug that is easy to ship.

The setup

Receipts runs the tests a change added or edited twice: with the change, and with the changed source files put back the way they were. For pytest it loads a tiny plugin that writes one JSON line per test result into a file, and the Node side reads that file afterwards.

def _emit(record):
    out = os.environ.get("RECEIPTS_PYTEST_OUT")
    if out:
        with open(out, "a", encoding="utf-8") as fh:
            fh.write(json.dumps(record) + "\n")

One file, opened in append mode, one line per record. Fine, until the project uses pytest-xdist. Then several worker processes run the tests, and at the end every one of them writes a record with the list of modules it imported. Those records are long, full of paths like \hostedtoolcache\windows\Python\.... That is the fragment in the error: the start of a line that got torn in half.

The repro

Four processes, each appending the same long JSON line 50 times to one file:

import json, os, multiprocessing as mp

def worker(out, n):
    rec = {"files": [r"\hostedtoolcache\windows\Python\Lib\m%04d.py" % i for i in range(400)]}
    for _ in range(n):
        with open(out, "a", encoding="utf-8") as fh:
            fh.write(json.dumps(rec) + "\n")

if __name__ == "__main__":
    out = "race.jsonl"
    ps = [mp.Process(target=worker, args=(out, 50)) for _ in range(4)]
    [p.start() for p in ps]; [p.join() for p in ps]
    print(sum(1 for _ in open(out, encoding="utf-8")), "lines")

On my Windows machine: 163 lines instead of 200. 37 writes simply vanished. With records of different lengths you also get torn lines instead of clean losses, which is what CI hit.

Why

On POSIX, O_APPEND means "move to the end and write" happens as one step for each write(), so concurrent appenders don't overwrite each other. On Windows, the C runtime emulates append mode: it seeks to the end, then writes. Two processes can both seek to the same end and the second write lands on top of the first. Nothing errors, data is just gone.

It only showed up now because it needs two xdist workers to finish within the same moment. It had been passing for weeks.

The fix

Stop sharing the file. The controlling process keeps out.json, each xdist worker writes out.json.<worker id>, and the reader picks up all of them:

worker = getattr(_config, "workerinput", None)
if worker is not None:
    out = "%s.%s" % (out, worker.get("workerid", os.getpid()))

While I was there, the reader stopped throwing on a line it can't parse: a run killed for hanging can leave a half-written last line, and the records before it still count.

The regression test doesn't try to reproduce the race (that would be a flaky test about flakiness). It checks the mechanism directly: a worker writes to its own file, the controller to the main one, and a torn line at the end doesn't sink the read. It fails on the old plugin and passes on the new one, which, given what the tool is for, felt like the least I could do.

Takeaway

If several processes append to one file, it works on Linux and macOS and loses data on Windows, quietly and rarely. Give each process its own file, or take a lock.

I drafted this post with an AI assistant. The error, the numbers and the code are from the actual CI run, my machine and the commit: https://github.com/syntaxixr/receipts/commit/70bb9b2

Comments

[Arhan Canli]

I ran your repro on macOS to see the POSIX side: four processes, 50 appends each of a 21,212-byte record, three runs, and every run gave 200 lines, all parseable. So the 'fine on Linux and macOS' half holds even for records well past a buffer size; the loss really is the Windows seek-then-write emulation.

One thing to check in the fix: the reader now picks up out.json.<worker id>. If a previous run in the same directory left out.json.gw0 behind (say the with-change run and the reverted run share an output path, or a CI cache keeps the folder), a glob on that prefix will mix stale records into the new result. Deleting the per-worker files at the start of each run, or putting the run id in the name, closes that.

Does the second run, the one with the source files put back, use a different RECEIPTS_PYTEST_OUT from the first?

[pm25coder]

Ran it on Windows, since that is the side the claim is about. It reproduces, and more often than one run suggests: six runs of your repro as posted (4 processes x 50 writes of the 21,212-byte record) lost something every time — 29, 35, 41, 41, 45 and 54 lines of 200, so 245 of 1,200 writes gone. Your 163 was mid-range.

Two things I could measure that your post states but does not show.

The torn lines are a different failure from the lost ones, and record length decides which you get. Holding every writer to the identical line: 15 runs across three sizes, and not one unparseable line — the losses are whole records, absent. Let the lengths differ and the damage changes shape:

                    records ok   torn (unparseable)   lost
equal, 76 B            911            0                 89  of 1000
equal, 2,143 B         815            0                185  of 1000
equal, 21,223 B        862            0                138  of 1000
unequal (0/7/14 B)     989           21                 11  of 1000

Equal lengths overwrite cleanly: the second writer lands on identical bytes, so a line disappears whole and the file stays parseable. Unequal lengths leave the tail of the overwritten record behind, and that is the state CI hit — a line that is present and unparseable rather than absent. So your parenthetical is right, and it is the difference between a count that is quietly short and the Unexpected token '\' you actually saw.

"Or take a lock" is not a peer of the per-file fix. Both stop the loss (200 of 200 in every run), but the same 200 writes took:

one file, no coordination   0.15 - 0.23 s      (and loses ~20% of the records)
one file per worker         0.19 - 0.22 s      200/200
a lock around each append   2.15 - 3.15 s      200/200

Ten to fifteen times the wall time for the same work, because each write pays a lock acquire and the file is opened per append. Worth knowing before reaching for the lock option.

One thing that surprised me: this is not the text layer. Four ways of making the same append — open(out, "a", encoding="utf-8") as you ship it, open(out, "ab") with pre-encoded bytes, os.open(..., O_APPEND | O_BINARY) with one os.write per record, and a single held descriptor with one os.write per record — all four lost records. Choosing a lower-level write does not narrow the window; only not sharing the file closes it.

On the stale-file hazard raised below: it is real where the precondition holds. Run 1 wrote 20 records as receipts.jsonl.gw0 and .gw1; running again into the same directory without deleting them, a reader that globs the prefix sees gw0:20, gw1:20 and counts 40. That cannot happen in this repo as shipped, though, because the directory itself is per run: src/runners/pytest.ts:82 makes a fresh mkdtempSync scratch and :83 puts out.json in it, while readRecords (:59-63) takes that directory and filters base or base.* inside it. So yes — the second run does get a different RECEIPTS_PYTEST_OUT, and the first run's parts are not in the second run's directory. Safe by construction rather than by cleanup, which is the better of the two.

That also explains why skipping a torn line (:66-73) is enough on its own here: with one file per process the only torn line left is a killed run's last one, which is exactly the case your end marker is checking for anyway.