|
ravel
Deterministic simulation testing for C++. Seed a bug, replay it exact.
|
The tutorial tested a network protocol. This example tests storage: a tiny key-value store that keeps its data in a write-ahead log, and what happens to it when the power fails. Disks are where the subtle bugs hide, because a disk lies in ways a network does not: it tells you a write is done when the data is still in memory, and a power cut can lose it, or tear it in half.
Two bugs to find, both real ones:
Every code block and every output block below is produced by the real programs in [docs/snippets](snippets); tools/check_docs.py keeps them honest.
The server appends every put to a log file, wal, as one line, PUT <key> <value>, and tells the client the put is stored. After a crash, the machine reboots and recovers by replaying the log from the start.
The server, one put at a time:
The order of the three things inside the loop is the whole story. In the correct version: write the record, sync the file (which forces it onto the disk), and only then acknowledge. A record is durable only after sync; before that it lives in the disk's cache, and a power cut may lose it or tear it (write only the first sector or two).
Notice alive(). When the power goes, this process is gone: it must stop, even if its last disk operation completed a moment earlier. (The porting guide explains why.)
Then a second task pulls the plug at a random moment and, a few ticks later, reboots and recovers:
and recovery itself is a loop over the log:
A crash can leave the last record cut off (it has no closing newline), so recovery must ignore a trailing fragment. That is the if (!complete ...) break line, and it is bug 2's hiding place.
The values are 600 bytes long on purpose: a disk sector is 512 bytes, so each record spans two sectors, which is what lets a torn write cut one in the middle.
Two properties, stated as invariants:
acknowledged_puts_survive**: if the client was told "stored", the value must be there after the crash. That is what "stored" means.recovery_invents_nothing**: everything recovery finds must be something that was actually written. A half-written value is not.kv_sweep runs the store under 500 seeds, with a --bug flag to pick the variant. The correct store first:
500 seeds, each with a power cut at a different moment and a different fate for whatever was unsynced, and no failures. Now the bugs.
The tempting optimization: tell the client "stored" as soon as the record is written, then sync afterwards (or in the background), so the client does not wait for the disk. It is faster, and it is wrong:
About one seed in six fails. The shrunk reproducer is 8 choices; let us read the run it describes. ravel_trace.py timeline (see the debugging guide) lays the trace out with one column per task and disk:
Read it top to bottom. The server writes put 1 at t=1 and syncs it at t=2; put 2 is written at t=6 and synced at t=11; put 3 is written at t=16, and the server (now at step 13) acknowledges it and starts its sync, which will take until t=21. But at t=20 the power_cut task pulls the plug: CRASH on the ssd column. The sync never finished. Put 3 was acknowledged and is gone.
The 8 choices say the same thing in numbers:
| Choice | Draw | Value | Meaning |
|---|---|---|---|
| 1st | which task runs first | 0 | the server |
| 2nd | write 1's latency | 0 | 1 tick |
| 3rd | when the power fails | 0 | at t=20, the earliest possible |
| 4th | sync 1's latency | 0 | 1 tick |
| 5th | write 2's latency | 3 | 4 ticks |
| 6th | sync 2's latency | 4 | 5 ticks |
| 7th | write 3's latency | 4 | 5 ticks |
| 8th | sync 3's latency | 4 | 5 ticks: it would finish at t=21, a tick too late |
And after that, the disk's own draw at the crash takes its default, 0: the unsynced write is lost. The bug needs nothing exotic: a slow disk and a power cut in a five-tick window.
Replay the saved reproducer, which lives in docs/snippets/data:
The fix is to swap the order back: sync, then acknowledge (the store above with --bug none).
The second bug is in recovery. Suppose a power cut hits while a record is being written: the disk may write the first sector and lose the rest, leaving a log that ends mid-record, with no closing newline. Correct recovery ignores that fragment. This variant believes it:
This time the invariant that breaks is recovery_invents_nothing: recovery invented a value nobody ever wrote (a real value with its tail sliced off), and it went into the store as if it were the truth. That is a subtler bug than losing data, because nothing looks wrong until you compare the value with what was written. It also only appears on the seeds where the power cut lands mid-write and the disk tears that write at a sector boundary, which is why it hit 25 seeds out of 500 and not more. Replay its reproducer:
Ask the correct store the same question, with the same reproducer, and it passes:
That is what a saved reproducer is for: it kept the exact moment that broke the buggy code, and it now guards the fixed code.
acknowledged_puts_survive), and check it after a crash. Half the value of this kind of test is writing that sentence down.Some experiments, each a few lines in kv_store.hpp:
wal.new file that is renamed over wal at checkpoints, and leave out sync_dir. (The disk tests show the safe recipe.){.write_error_probability = 0.05} in the disk's fault spec. What should the server do when a write fails? Does your answer survive the sweep?For a bigger system that combines all of this (crashing nodes, disks, a lossy network), read the Raft example.
1.9.8