Files
packfs/tests/test_crash_consistency.c
retoorandClaude Sonnet 5 c414a27e44
CI / build-and-test (push) Successful in 41s
Fix CI's actual root cause: a set -e scripting bug, not a code bug
The reported failure -- "Build and run under ThreadSanitizer" exiting
with code 66 -- traced back to a real bug in .gitea/workflows/ci.yml
itself, confirmed by direct reproduction, not just theorized:

1. Root cause: this step's default shell runs under `set -e`. The
   previous version assigned OUT via a bare, unwrapped
   `OUT=$("./binary" 2>&1)` -- under `-e`, that command's own nonzero
   exit status aborts the whole script immediately, *before* the very
   next line (even `RC=$?`) ever runs. Confirmed with a two-line
   reproduction: `OUT=$(false); echo "after"` under `set -e` never
   prints "after". This meant none of the step's careful classification
   logic (distinguishing the known TSan-can't-start-here limitation from
   a real finding) ever executed -- the first binary to hit the FATAL/
   exit-66 case (all of them, on this runner) killed the step outright
   with that raw exit code, exactly the outcome the classification logic
   exists to prevent. Fixed by wrapping every such invocation in
   `if cmd; then RC=0; else RC=$?; fi`, which bash's `-e` rules exempt
   from triggering an abort -- verified directly under `bash -eo
   pipefail` (matching Gitea Actions' actual shell), not assumed correct.

2. Fixing (1) surfaced a second bug: capturing potentially unbounded
   output into a bash variable via `OUT=$(cmd)` is not just slow, it
   reproduced as a several-hundred-megabyte shell string when the
   DEADLYSIGNAL flake's worse, unbounded-repeating-loop form hit during
   this fix's own testing -- and caused the classification logic to
   misbehave at that scale (a real failure was misreported with "exit
   0"). Fixed in both the ASan/UBSan and TSan steps by redirecting
   output to a file and reading back only a bounded 64 KiB prefix for
   classification and logging, never loading the whole thing into a
   shell variable.

3. While repeatedly reproducing the TSan flake locally to verify (1) and
   (2), found a second, previously undocumented variant of the same
   underlying "TSan can't start on this runner" issue: instead of
   printing FATAL: ThreadSanitizer: unexpected memory mapping and
   exiting 66, TSan's broken startup occasionally segfaults outright.
   Confirmed this is the same environmental cause, not a bug in any
   specific test file, by hitting three different, unrelated binaries
   (test_journal_failure in one run, test_crash_consistency and test_dir
   together in another) across repeated full-suite runs -- a real bug
   in one file's code would not migrate to different files at random.
   The TSan step's classification now recognizes this variant too
   (a log containing only timeout's own "dumped core" notice and nothing
   else -- no program output, no real WARNING/SUMMARY ThreadSanitizer
   race report).

4. The ASan/UBSan step's retry budget was bumped from 3 to 5 after
   observing a real 3-in-a-row flake exhaustion in practice during this
   same verification work -- this sandbox's actual flake rate is
   meaningfully higher than the "roughly 1 in 5-10" CONTRIBUTING.md
   documents, and 3 retries turned out not to be a big enough margin.

5. Separately, the -Wunused-result warning on tests/test_crash_consistency.c's
   write() call: the (void) cast that silenced it locally did not silence
   it on the Gitea runner's gcc -- reproduced clean locally with the
   exact same compiler flags, confirming this is a real toolchain
   version/config difference, not a local misconfiguration. void-cast
   suppression of warn_unused_result is documented as unreliable across
   gcc configurations; fixed with an actual conditional branch on the
   return value instead, which every gcc/clang version used so far
   honors.

Every fix here was verified by direct reproduction under `bash -eo
pipefail` locally (matching Gitea Actions' actual shell invocation), not
reasoned about and assumed correct: the original -e bug was reproduced
and fixed, the TSan step was re-run 10 full-suite times (80 individual
binary executions) with both flake variants recurring and both correctly
classified as warnings rather than errors, and the ASan/UBSan step was
re-run 10 full-suite times with the 5-retry budget with zero false
failures. Also verified with a clean make all + make test locally
(zero warnings, all 8 binaries pass).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01UqJpkdJ6Njnt1pw3CbghzB
2026-09-14 20:55:54 +00:00

413 lines
17 KiB
C

/*
* test_crash_consistency.c — real fault injection for Section 4.3/4.4's
* crash-safety claims (self-checking journal records, atomic-rename
* compaction), via an actual fork()+SIGKILL of a child mid-operation and
* a fresh reopen afterward, not a hand-truncated file standing in for a
* crash. The two scenarios below (journal writes, compaction) were the
* two concrete claims CLAUDE.md/concept.md make about crash behavior;
* before this file, neither had ever actually been exercised by killing
* a real process mid-write — only by static reasoning about the design
* and by test_pack_overlay.c's separate (unrelated) test of loading an
* already-corrupted pack file.
*
* Timing constants below are empirically calibrated for this project's
* own build (see the comment above each scenario), not arbitrary: the
* goal is to sample kill delays across the real duration of the
* operation under test, confirmed per-run by reporting how many trials
* actually landed a genuine mid-operation kill (WIFSIGNALED) versus how
* many the child outran (WIFEXITED) — a run reporting zero interrupted
* trials would mean this test verified nothing and should be treated as
* a test bug, not a pass; see the CHECK on INTERRUPTED_MIN below.
*/
#include <fcntl.h>
#include <signal.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/wait.h>
#include <time.h>
#include <unistd.h>
#include "packfs.h"
#include "test_harness.h"
static void sleep_sec(double s) {
struct timespec ts;
ts.tv_sec = (time_t)s;
ts.tv_nsec = (long)((s - (double)ts.tv_sec) * 1e9);
nanosleep(&ts, NULL);
}
/* fork the given child function, let it run for kill_delay seconds, then
* SIGKILL it. Returns 1 if the child was genuinely still running (killed
* by the signal), 0 if it had already exited on its own. */
static int run_and_kill(void (*child_fn)(void *), void *arg, double kill_delay) {
pid_t pid = fork();
if (pid < 0) { perror("fork"); exit(1); }
if (pid == 0) {
child_fn(arg);
_exit(99); /* child_fn must _exit itself; this is a safety net */
}
sleep_sec(kill_delay);
kill(pid, SIGKILL);
int status = 0;
waitpid(pid, &status, 0);
return WIFSIGNALED(status) && WTERMSIG(status) == SIGKILL;
}
/* ================= scenario A: kill mid-burst of journaled writes ===== */
/*
* Calibrated: ~6ms per individual journaled create+write+close on this
* build/environment (fopen+fwrite+fflush+fsync per record, Section 4.4).
* BURST=60 writes takes ~0.36s; sampling kill delays across [0, 0.40s]
* covers the whole burst including its very start and its tail.
*/
#define BURST_N 60
#define BURST_TRIALS 25
#define BURST_MAX_DELAY 0.40
typedef struct { char pack_path[512]; } BurstArg;
static void mk_burst_content(char *buf, size_t n, int i) {
snprintf(buf, n, "burst-content-%06d", i);
}
static void burst_child(void *arg_) {
BurstArg *arg = (BurstArg *)arg_;
Vfs *v = vfs_new();
Backend *mem = backend_mem_new();
int oerr = 0;
Backend *ov = backend_overlay_new(arg->pack_path, mem, &oerr);
if (!ov) _exit(2);
if (vfs_mount(v, "/", ov) != VFS_OK) _exit(3);
char name[64], content[64];
for (int i = 0; i < BURST_N; i++) {
snprintf(name, sizeof(name), "/f%05d.txt", i);
mk_burst_content(content, sizeof(content), i);
int err = 0;
VfsFile *f = vfs_open(v, name, VFS_O_WRONLY | VFS_O_CREAT, &err);
if (!f) _exit(4);
if (vfs_write(f, content, strlen(content)) != (pfs_isize)strlen(content)) _exit(5);
if (vfs_close(f) != VFS_OK) _exit(6);
}
_exit(0); /* all BURST_N writes durably committed */
}
static void test_journal_burst_crash(void) {
BurstArg arg;
snprintf(arg.pack_path, sizeof(arg.pack_path), "/tmp/packfs_test_crash_burst_%d.img", (int)getpid());
char jpath[600];
snprintf(jpath, sizeof(jpath), "%s.jnl", arg.pack_path);
int interrupted_count = 0;
for (int trial = 0; trial < BURST_TRIALS; trial++) {
unlink(arg.pack_path);
unlink(jpath);
double delay = (BURST_MAX_DELAY * (double)trial) / (double)(BURST_TRIALS - 1);
int interrupted = run_and_kill(burst_child, &arg, delay);
if (interrupted) interrupted_count++;
Vfs *v2 = vfs_new();
Backend *mem2 = backend_mem_new();
int oerr2 = 0;
Backend *ov2 = backend_overlay_new(arg.pack_path, mem2, &oerr2);
CHECK(ov2 != NULL); /* a crash mid-journal must never make reopening fail */
if (!ov2) { vfs_free(v2); backend_free(mem2); continue; }
CHECK_EQ_INT(vfs_mount(v2, "/", ov2), VFS_OK);
/* clean-prefix invariant: every present file has exactly correct
* content, and there is no gap (file i missing, file i+1 present) */
int last_present = -1;
char name[64], expect[64], buf[64];
for (int i = 0; i < BURST_N; i++) {
snprintf(name, sizeof(name), "/f%05d.txt", i);
int err = 0;
VfsFile *f = vfs_open(v2, name, VFS_O_RDONLY, &err);
if (!f) continue;
mk_burst_content(expect, sizeof(expect), i);
memset(buf, 0, sizeof(buf));
pfs_isize n = vfs_read(f, buf, sizeof(buf));
vfs_close(f);
if (n != (pfs_isize)strlen(expect) || memcmp(buf, expect, strlen(expect)) != 0) {
fprintf(stderr, "FAIL trial %d: %s has wrong/corrupt content after crash (delay=%.4f)\n",
trial, name, delay);
pfs_test_failures++;
}
if (i != last_present + 1) {
fprintf(stderr, "FAIL trial %d: gap in journal replay prefix at %s (delay=%.4f)\n",
trial, name, delay);
pfs_test_failures++;
}
last_present = i;
}
vfs_unmount(v2, "/");
backend_free(ov2);
backend_free(mem2);
vfs_free(v2);
}
unlink(arg.pack_path);
unlink(jpath);
fprintf(stderr, "journal-burst crash test: %d/%d trials genuinely interrupted mid-burst\n",
interrupted_count, BURST_TRIALS);
/* if this is ever 0, the delay schedule no longer matches this
* machine's write latency and the test isn't exercising the crash
* path at all -- that is itself a failure, not a quiet pass. */
CHECK(interrupted_count >= BURST_TRIALS / 4);
}
/* ================= scenario B: kill mid-compaction ===================== */
/*
* Calibrated: a 100-file, 2KB-payload durable baseline (built once,
* untimed, then compacted once to get a clean golden pack.img) plus a
* per-trial 10-file durable "extras" batch takes ~0.058s to journal and
* the following compaction takes ~0.012s on this build/environment.
* Sampling kill delays across [0, 0.08s] covers extras-journaling,
* compaction start, mid-compaction, and post-rename.
*
* The invariant under test is not "pre-state XOR post-state" -- it's
* simpler and is the actual documented guarantee (concept.md's crash-
* safety constraints, CLAUDE.md's "if writing pack.img.tmp or its fsync
* fails, compaction aborts and the existing pack + journal are
* untouched"): anything durably journaled (fsynced) *before* vfs_sync is
* even called must survive a crash during that vfs_sync call, no matter
* where in it the crash lands -- either via journal replay (if
* compaction didn't finish) or by being included in the fresh pack (if
* it did).
*/
#define GOLDEN_N 100
#define EXTRA_N 10
#define PAYLOAD_SIZE 2048
#define COMPACT_TRIALS 40
#define COMPACT_MAX_DELAY 0.08
typedef struct { char pack_path[512]; char golden_path[512]; char progress_path[512]; } CompactArg;
static void mk_payload(char *buf, size_t n, const char *tag, int i) {
int len = snprintf(buf, n, "%s-%06d-", tag, i);
for (size_t j = (size_t)len; j < n; j++) buf[j] = (char)('a' + (int)(j % 26));
}
static int copy_file(const char *from, const char *to) {
FILE *in = fopen(from, "rb");
if (!in) return -1;
FILE *out = fopen(to, "wb");
if (!out) { fclose(in); return -1; }
char buf[65536];
size_t n;
while ((n = fread(buf, 1, sizeof(buf), in)) > 0) fwrite(buf, 1, n, out);
fclose(in);
fclose(out);
return 0;
}
/* Records "N extras durably completed" via a plain POSIX write+fsync on a
* dedicated file, entirely independent of packfs. This is the test's
* ground truth for how far the child actually got before SIGKILL landed
* -- without it, an extra that the child simply never reached in time
* (expected, not a bug) is indistinguishable from one that completed and
* was then lost (a real bug), since SIGKILL cannot be caught to report
* progress any other way. The one imprecision this leaves: the tiny gap
* between vfs_close() returning (extra i durably in the journal) and
* this progress write's own fsync landing can make the progress count
* undercount by one extra in the worst case -- which only makes the
* check *less* strict at the margin (skips verifying the most recent
* extra), never produces a false failure. */
static void record_progress(const char *progress_path, int n_done) {
int fd = open(progress_path, O_WRONLY | O_CREAT | O_TRUNC, 0644);
if (fd < 0) return;
char buf[16];
int len = snprintf(buf, sizeof(buf), "%d", n_done);
/* Best-effort: a short write here only makes read_progress()'s count
* more conservative (see the imprecision note above), never wrong in
* the unsafe direction, so there is nothing more useful to do with a
* failed/partial write than note it happened. A bare `(void)` cast
* looked like the idiomatic way to silence write()'s
* warn_unused_result attribute, but proved unreliable in practice —
* it built warning-free here, then still warned under the Gitea
* runner's gcc (a real, observed toolchain-version/config
* difference, not a local misconfiguration on either side); an
* actual branch on the result, below, is honored by every gcc/clang
* version this project has been built with so far. */
if (write(fd, buf, (size_t)len) < 0) { /* best-effort; nothing more to do */ }
fsync(fd);
close(fd);
}
static int read_progress(const char *progress_path) {
FILE *fp = fopen(progress_path, "r");
if (!fp) return 0;
int n = 0;
if (fscanf(fp, "%d", &n) != 1) n = 0;
fclose(fp);
return n;
}
static void compact_child(void *arg_) {
CompactArg *arg = (CompactArg *)arg_;
record_progress(arg->progress_path, 0);
Vfs *v = vfs_new();
Backend *mem = backend_mem_new();
int oerr = 0;
Backend *ov = backend_overlay_new(arg->pack_path, mem, &oerr);
if (!ov) _exit(2);
if (vfs_mount(v, "/", ov) != VFS_OK) _exit(3);
char payload[PAYLOAD_SIZE];
for (int i = 0; i < EXTRA_N; i++) {
char name[64];
snprintf(name, sizeof(name), "/extra%04d.dat", i);
mk_payload(payload, sizeof(payload), "extra", i);
int err = 0;
VfsFile *f = vfs_open(v, name, VFS_O_WRONLY | VFS_O_CREAT, &err);
if (!f) _exit(4);
if (vfs_write(f, payload, sizeof(payload)) != (pfs_isize)sizeof(payload)) _exit(5);
if (vfs_close(f) != VFS_OK) _exit(6);
record_progress(arg->progress_path, i + 1); /* extra i is now durable */
}
/* every extra above is already durable (each fsynced individually);
* this is the operation actually being crash-tested */
if (vfs_sync(v, "/") != VFS_OK) _exit(7);
_exit(0);
}
static void build_golden_baseline(CompactArg *arg) {
unlink(arg->pack_path);
char jpath[600];
snprintf(jpath, sizeof(jpath), "%s.jnl", arg->pack_path);
unlink(jpath);
Vfs *v = vfs_new();
Backend *mem = backend_mem_new();
int oerr = 0;
Backend *ov = backend_overlay_new(arg->pack_path, mem, &oerr);
CHECK(ov != NULL);
CHECK_EQ_INT(vfs_mount(v, "/", ov), VFS_OK);
char payload[PAYLOAD_SIZE];
for (int i = 0; i < GOLDEN_N; i++) {
char name[64];
snprintf(name, sizeof(name), "/base%05d.dat", i);
mk_payload(payload, sizeof(payload), "base", i);
int err = 0;
VfsFile *f = vfs_open(v, name, VFS_O_WRONLY | VFS_O_CREAT, &err);
CHECK(f != NULL);
CHECK_EQ_INT(vfs_write(f, payload, sizeof(payload)), (pfs_isize)sizeof(payload));
CHECK_EQ_INT(vfs_close(f), VFS_OK);
}
CHECK_EQ_INT(vfs_sync(v, "/"), VFS_OK); /* clean, untimed compaction */
vfs_unmount(v, "/");
backend_free(ov);
backend_free(mem);
vfs_free(v);
unlink(jpath); /* golden state: compacted pack, no pending journal */
CHECK_EQ_INT(copy_file(arg->pack_path, arg->golden_path), 0);
}
static void test_compaction_crash(void) {
CompactArg arg;
snprintf(arg.pack_path, sizeof(arg.pack_path), "/tmp/packfs_test_crash_compact_%d.img", (int)getpid());
snprintf(arg.golden_path, sizeof(arg.golden_path), "/tmp/packfs_test_crash_golden_%d.img", (int)getpid());
snprintf(arg.progress_path, sizeof(arg.progress_path), "/tmp/packfs_test_crash_progress_%d.txt", (int)getpid());
char jpath[600];
snprintf(jpath, sizeof(jpath), "%s.jnl", arg.pack_path);
build_golden_baseline(&arg);
int interrupted_count = 0;
for (int trial = 0; trial < COMPACT_TRIALS; trial++) {
CHECK_EQ_INT(copy_file(arg.golden_path, arg.pack_path), 0);
unlink(jpath);
double delay = (COMPACT_MAX_DELAY * (double)trial) / (double)(COMPACT_TRIALS - 1);
int interrupted = run_and_kill(compact_child, &arg, delay);
if (interrupted) interrupted_count++;
Vfs *v2 = vfs_new();
Backend *mem2 = backend_mem_new();
int oerr2 = 0;
Backend *ov2 = backend_overlay_new(arg.pack_path, mem2, &oerr2);
CHECK(ov2 != NULL); /* a crash mid-compaction must never make reopening fail */
if (!ov2) { vfs_free(v2); backend_free(mem2); continue; }
CHECK_EQ_INT(vfs_mount(v2, "/", ov2), VFS_OK);
/* the pre-existing golden baseline must always survive */
char name[64], expect[PAYLOAD_SIZE], buf[PAYLOAD_SIZE];
for (int i = 0; i < GOLDEN_N; i++) {
snprintf(name, sizeof(name), "/base%05d.dat", i);
mk_payload(expect, sizeof(expect), "base", i);
int err = 0;
VfsFile *f = vfs_open(v2, name, VFS_O_RDONLY, &err);
if (!f) {
fprintf(stderr, "FAIL trial %d: baseline file %s LOST after compaction crash (delay=%.4f)\n",
trial, name, delay);
pfs_test_failures++;
continue;
}
memset(buf, 0, sizeof(buf));
pfs_isize n = vfs_read(f, buf, sizeof(buf));
vfs_close(f);
if (n != (pfs_isize)sizeof(buf) || memcmp(buf, expect, sizeof(buf)) != 0) {
fprintf(stderr, "FAIL trial %d: baseline file %s CORRUPTED after compaction crash (delay=%.4f)\n",
trial, name, delay);
pfs_test_failures++;
}
}
/* Every "extra" write the child actually completed (vfs_close
* returned VFS_OK) before it was killed was already durably
* journaled at that point -- it must survive regardless of
* whether the subsequent vfs_sync (compaction) itself completed.
* completed_extras, from the independent progress side-channel,
* is the ground truth for how many extras the child actually
* finished; extras beyond that were never attempted and their
* absence is expected, not a bug. */
int completed_extras = read_progress(arg.progress_path);
CHECK(completed_extras >= 0 && completed_extras <= EXTRA_N);
for (int i = 0; i < completed_extras; i++) {
snprintf(name, sizeof(name), "/extra%04d.dat", i);
mk_payload(expect, sizeof(expect), "extra", i);
int err = 0;
VfsFile *f = vfs_open(v2, name, VFS_O_RDONLY, &err);
if (!f) {
fprintf(stderr, "FAIL trial %d: durably-completed %s LOST after compaction crash "
"(delay=%.4f, completed_extras=%d)\n", trial, name, delay, completed_extras);
pfs_test_failures++;
continue;
}
memset(buf, 0, sizeof(buf));
pfs_isize n = vfs_read(f, buf, sizeof(buf));
vfs_close(f);
if (n != (pfs_isize)sizeof(buf) || memcmp(buf, expect, sizeof(buf)) != 0) {
fprintf(stderr, "FAIL trial %d: durably-completed %s CORRUPTED after compaction crash "
"(delay=%.4f, completed_extras=%d)\n", trial, name, delay, completed_extras);
pfs_test_failures++;
}
}
vfs_unmount(v2, "/");
backend_free(ov2);
backend_free(mem2);
vfs_free(v2);
}
unlink(arg.pack_path);
unlink(arg.golden_path);
unlink(arg.progress_path);
unlink(jpath);
fprintf(stderr, "compaction crash test: %d/%d trials genuinely interrupted mid-compaction\n",
interrupted_count, COMPACT_TRIALS);
CHECK(interrupted_count >= COMPACT_TRIALS / 4);
}
int main(void) {
test_journal_burst_crash();
test_compaction_crash();
TEST_MAIN_END();
}