wal-crash

A crash-consistency tester for storage code. It records every file-system operation a program makes, builds every state a power failure could leave the directory in, runs the program's own recovery on each one, and says which promise broke and which lost operation broke it.

Killing the process proves very little: the operating system survives a kill -9, and so does every write in its page cache. A power failure is different. Whatever no fsync covered may be lost, kept or half-written, in any combination. A missing directory fsync, an acknowledgement sent one line too early, a checksum recovery never checks: they pass every test that doesn't model the disk.

View on GitHub What it found

Plays the six stages below in order, about 55 seconds. Scroll or press Esc to stop.

Language
Go 1.23 or newer
Tests
35 passing with go test -race, end to end under real strace
Dependencies
None: the Go standard library, and strace to record
Models
process, ordered and posix
Runs on
Linux with strace; the Makefile can run everything in Docker
Exit codes
0 if every state passed, 1 if any failed, 2 if it couldn't do the job
License
MIT
wal-crash run --model all --checker "$kv -engine log -bug ack-before-fsync -dir . check" -- $kv -engine log -bug ack-before-fsync -dir {dir} load 5 22 operations recorded, 5 acknowledged process 23 states (17 distinct) checked PASS ordered 38 states (32 distinct) checked PASS posix 64 states (52 distinct) checked FAIL 20 of them break the checker

Real runs of wal-crash at commit 436cd30 in its own Docker image (Go 1.25, strace 6.13, SQLite 3.46.1), output verbatim. $kv is the repository's small key-value store, which can switch on six planted durability bugs. The SQLite tabs run six transactions in rollback-journal mode at synchronous=FULL and EXTRA.

1Record every file-system call

wal-crash record runs the workload under strace -f -y -xx -s 64M, which logs every system call with the full bytes written and the path behind every file descriptor. A parser replays that log against a model of the directory and turns it into operations.

  • Descriptors are shared the way the kernel shares them: dup and fork share the position, threads share the table, O_APPEND writes go to the end. That is how a plain write() gets its offset.
  • A call strace split in two, <unfinished ...> and resumed, is joined back together. Lines printed on standard output become operations too, so each acknowledgement sits at its exact place.
  • What it can't model is refused, not ignored: hard and symbolic links, RENAME_EXCHANGE, O_TMPFILE, copy_file_range, sendfile.

One put, 26 strace lines, 7 operations

      The strace lines are 53 to 78 of the repository's golden log, internal/strace/testdata/kvstore-snapshot.strace: the snapshot store putting k1. strace's \x escapes are decoded here for reading, and long lines are cut. The operations are the first seven of the golden .ops file, which CI checks the parser against. The refusals are real runs on two one-line shell workloads made for this page Illustrative input.

      2Work out what each fsync promised

      The file system is a set of inodes, and every operation names the inode it changes. An operation is forced once a sync that covers it has completed. Everything else is pending: it may or may not have reached the disk, independently of the others.

      • fsync of a file covers that file's earlier writes and truncates.
      • fsync of a directory covers earlier entry changes in it: create, rename, unlink. A rename between two directories needs both synced.
      • sync covers everything.

      Because operations name inodes, a lost operation doesn't break the ones after it. A write to a file whose creation never reached the disk lands on an inode nothing points to, which is what a real disk would hold.

      The snapshot store, and the same store without its directory fsync

      Never synced: may be lostA syncA promise to the caller
      Both columns are the first two puts of wal-crash ops on a real recording, five puts each. ops marks every operation no later sync covers as (never synced); on the correct store there are none.

      3Build every state a crash could leave

      A crash happens after some operation. What survives depends on the persistence model, and wal-crash checks all three.

      • process: the program dies and the OS doesn't. Everything before the crash is kept, in order.
      • ordered: power fails on a disk that wrote in order. As process, but the last write may be torn.
      • posix: only what fsync promised survives. Per crash point it tries everything pending kept, nothing kept, each one lost alone, each one kept alone, and each pending write torn three ways: half, short or zeros.
      • All subsets would be 2k states per crash point, so like ALICE and CrashMonkey this is a bounded search. States with the same files and the same output are checked once.

      The log store, five puts, every state explored

      Checked, passedChecked, failedSame files and output as another stateAAn acknowledgement
      Columns are crash points: after 0 to 22 of the 22 operations. Rows are the kinds of state, as wal-crash names them (c5.synced is "crash after op 5, only what was synced"). The states and the verdicts were listed by a scratch program added to a copy of the repository, which calls wal-crash's own explorer and runs the store's checker on every state; its counts match the wal-crash run output in the hero.

      RecoveredAbove this line wal-crash records the run and builds the disk states a crash could leave. Below it, the program's own recovery runs on each one, and the checker decides whether the promise held.

      4Let the program's own recovery be judged

      wal-crash doesn't decide what correct means. A checker does: a shell command run inside each state's directory, in parallel, one temporary directory each. It opens the data the way the program does after a restart, so the recovery code runs, and exits non-zero, saying why, if something is wrong.

      • The workload makes a promise by printing a line that starts with ACK . The checker gets the promises made before the crash, and everything printed, to know what was attempted.
      • The usual invariant: recovery succeeds, every acknowledged write is there, and nothing is there that was never written.
      • The first state is checked alone, so a checker that can't run fails fast instead of thousands of times. A hung recovery counts as a failure after --timeout.

      What the checker sees in state c5.synced

      The variables are the README's contract. The terminal is real: the early-ACK log store's state c5.synced written out with wal-crash state, its file and its acknowledgements listed, then a run with a checker that doesn't exist, which stops after the first state with exit code 2.

      5Report the simplest failure, and the lost operation

      Of every failing state, the one reported is the simplest: the fewest operations lost or torn, then the earliest crash, then a lost operation before a torn one. Usually it is one missing operation just before an acknowledgement, which reads directly as the bug.

      • The lost operation is marked, with why it could be lost: no fsync of the file, or of the directory, after it.
      • The other failing states are grouped by their message, with the numbers taken out, so the report says how many kinds of failure there are.
      • With -o trace.json, a reproduce: line names the state to write out.

      Three stores, three simplest failures

      Real wal-crash run output under the default posix model. The SQLite run is rollback-journal mode at synchronous=NORMAL; its checker opens the database with the sqlite3 CLI, so SQLite's own hot-journal rollback runs, then requires PRAGMA integrity_check to say ok.

      6Write the state out, and look at it

      wal-crash state writes one crash state to a directory: the files as the disk would hold them, the acknowledgements and the output. Run the checker there, or open the files, and the failure happens again, outside the tool.

      • The skip-dir-fsync store renamed its new file into place and never synced the directory. In the state below, the rename is lost: data.tmp is there, data isn't, and k1 was acknowledged.
      • The SQLite NORMAL state shows why a corrupt database is possible: the journal's header reached the disk and one of its pages didn't.

      SQLite's journal checksum samples one byte in 200, and on that page those bytes were zero anyway, so a page of zeros passes. Rollback restores it over a btree page. With FULL, the pages are synced before the header is written, so this can't happen: every FULL failure is a lost commit, never a corrupt database.

      Two states, written out

      The first terminal is real, in the dev image. The journal records below it are state c24.drop16 of the SQLite NORMAL run, written out with wal-crash state on this machine and decoded with a short script written for this page, which reads SQLite's documented journal format and recomputes each record's checksum. It reproduces the README's table exactly.

      Measured, not assumed

      SQLite 3.46.1, six transactions each acknowledged when COMMIT returns, under every journal mode and sync level the repository tests. Run here in the dev image; make matrix reproduced the committed docs/matrix.txt byte for byte.

      Agrees with SQLite's documentation

      Every row agrees with SQLite's documentation for PRAGMA synchronous, and every off row passes process and fails posix: it survives a killed program, not a power cut.

      delete, full loses the last commit because the journal's unlink, which is the commit, is never made durable by a directory fsync. That is the case SQLite gives as the reason EXTRA exists.

      Killing the process finds one bug in six

      The key-value store's six planted bugs, each under the three models:

      Only write-in-place fails under process. no-crc needs a torn write, and the other four need a model of what fsync promised.

      What it costs

      The states grow with operations times pending ones, so it is meant for small, focused workloads.

      35 tests, against real kernel output

      Counted with go test -race -json ./... in the dev image, as CI's make test runs them: 33 test functions and the 2 subtests of the golden-trace test, all passing. The repository's README says 34 test functions; the 34th func Test is TestMain, which builds the binaries for the end-to-end tests.

        Weighted toward the parser and the models

        • Lexer and parser: strace's quoting, interrupted calls joined back together, positions through dup, fork and threads, O_APPEND, writev, renames between directories, and refusals.
        • Golden traces: real strace logs from the Go store and from SQLite in WAL mode, and the operations each must produce.
        • Model: the three torn-write shapes, renames and unlinks that tolerate lost dependencies, hashes that ignore unreachable inodes, a materialize and diff round trip.
        • Models and enumeration: what each sync forces, a rename between two directories, and that posix finds a lost rename process and ordered can't.
        • Runner and end to end: the simplest violation, deduplication, a broken checker failing fast, timeouts as failures; the real binary under strace finds the planted bug, and its reproduce: line writes a state that fails the same way.

        CI runs gofmt, vet and the tests in the dev image and on an Ubuntu host with Go 1.23 and stable, then reruns both tables and fails if a verdict or a byte of docs/matrix.txt changes.

        Deliberately missing

        Exhaustiveness
        The search is bounded. A bug that needs two particular operations lost and a third kept can be missed.
        A real file system
        posix is weaker than ext4, XFS or btrfs as configured by default. A failure under it violates POSIX, but may not happen on your file system today.
        mmap and io_uring
        strace sees system calls, and a store through a shared mapping isn't one. Such writes are treated as never reaching the disk, with a warning.
        Judging correctness
        The checker does that. A weak checker, one that only opens the database, passes states a strong one would fail.

        Run it

        git clone https://github.com/ahmed-hashim-pro/wal-crash.git
        cd wal-crash
        make build    # bin/wal-crash, kvstore, sqlite-workload
        make test     # gofmt, vet, 35 tests
        make matrix   # both tables
        
        docker run --rm -it -u $(id -u):$(id -g) -e HOME=/tmp \
          -v $PWD:/w -w /w wal-crash-dev bash
        export PATH=$PWD/bin:$PATH kv=$PWD/bin/kvstore
        wal-crash run --model all \
          --checker "$kv -engine log -dir . check" \
          -- $kv -engine log -dir {dir} load 5

        The Makefile runs everything in a Docker image with Go, strace and SQLite, so Docker alone is enough. On Linux with Go 1.23 or newer and strace, make build test matrix LOCAL=1 skips Docker.