Four Sanity Patterns for Distributed-System Testing

Four traps I've walked into (and out of) while writing fault-injection tests
against a distributed system. Each one produced a vacuous pass or a false
diagnosis — the test looked fine, or the log looked damning, but the
reality was the opposite. Each has a durable escape recipe.

They all share one shape: you think you're observing X, but you're
observing Y. The escape is always to add a second, independent channel
of observation before trusting the first.

---

1. Cumulative-log fallacy

Trap. A long-running daemon appends to the same log file across many
test iterations. Your test greps the file for a marker
("parent died", "failed to init", "shutting down"). The grep hits —
but the hit is from a prior teardown, not the current run. Read as
current state, it produces a false diagnosis with high confidence.

Concrete failure I hit. Testing a scheduler daemon on a shared host:

1. Test 1 teardown calls the shutdown helper. Scheduler logs "parent has died" on the way out. That line is now permanent.
2. Test 2 setup starts a fresh scheduler. It's alive and healthy.
3. My test tails the log, sees "parent died", concludes "scheduler exits during init — must be transient on this build."
4. I xfail five test cases with the wrong premise and file a comment asking dev what changed.

A reviewer opened the same log, spotted the shutdown call immediately
above the parent died line, and pointed out the message was from
teardown, not natural exit. Scheduler was daemon-mode the whole time.

Root cause. grep has no time axis. The signal
("parent died") truly means "the scheduler exited" — but the
timestamp matters more than the text, and grep ignores it.

Escape recipes — pick the cheapest that fits:

• Nonce: write a uuid4().hex somewhere the daemon echoes on startup (config file, env-var-driven log marker). Grep starts at the line containing the nonce.
• Byte offset: snapshot os.stat(log).st_size before the action; grep only content[offset:]. Caveat: brittle if the daemon rotates the log or opens a new one.
• Truncate: rotate or truncate the log at fixture setup. Cheapest of all when the log is per-test-run and not a durable audit trail.

The rule. Never grep <pattern> <log> without a since-when anchor
when the fixture restarts the daemon.

Companion checks before publishing a "the daemon did X" claim:

1. Is the line I'm quoting from this run? (log timestamp vs fixture clock)
2. Does the live process table agree with the log? (alive PID and recent line)
3. Did anything in the fixture issue a stop between the action and the observation?

Any "no / don't know" → cumulative-log risk.

---

2. Silent filter miss

Trap. Your test predicate — _pgrep, _find_child, is_x_running —
returns empty. There are two indistinguishable causes:

1. The target really isn't there.
2. Your filter is wrong; the target IS there but you missed it.

Cause (2) produces no error, only silence. You can chase ghost theories
about (1) for hours.

Concrete failure I hit. My predicate was
pgrep -f $INSTALL_ROOT -a looking for the scheduler binary path. On the
build I was testing, the scheduler's argv was bare
scheduler --writefd 6 — no install-root prefix, because it was
fork-exec'd from the parent with a constructed argv. Filter returned
empty every time.

I built a story to explain the silence: "scheduler is transient on this
build, exits during init, that's why I never see it." Wrote a comment
to dev, xfail'd five tests, updated memory. All wrong.

What broke the loop was running the same query outside my code:
pgrep -af scheduler in the shell — with no install-root gate —
returned a live PID with scheduler --writefd 6 in the cmdline. Alive
the whole time. My filter was the bug.

Root cause. A predicate with one overly-strict gate returns empty
identically to a truly-absent target. Absence claims from filters are
vacuous — until you cross-check them.

Escape recipes.

• Independent observation — verify absence with a channel that does NOT go through the same filter your code uses. ps -eo pid,cmd, ls -l /proc/*/exe, ss -lntp, direct log tail. Different axis, no shared gate.
• Introspect the filter axis — if your code matches by argv, print the target's actual argv first. Fork-exec'd children often have constructor-built argv. systemd/launchd services often set comm but not argv.
• Test each gate independently — if the filter has 3 gates (--user=X --root=Y --name=Z), verify each in isolation. A single wrong gate kills the match.

The smell signal. If you catch yourself constructing a story to
explain a persistent, deterministic empty result, the story is
probably wrong. Real intermittent absence is racy / time-dependent; a
filter bug is deterministic. Deterministic absence + plausible
explanation = check the filter, not the story.

---

3. Polling-fire window

Trap. You're testing a scheduler (or any polling-config system) that
re-reads its config every N seconds. You install a test entry whose
fire time is before the next poll boundary. When the scheduler
finally polls, the entry looks past-due, and the "past entries wait
until next day" rule kicks in. The entry never runs in your test
window. There is no error log. The install lines look identical to
a normal case.

Concrete failure I hit. Scheduler's config-refresh poll interval was
60 s. My test:

fire_at = now + 10  # 10 seconds from wall-clock

Timeline:

T (s)	Event
0	test writes a job entry fire_at = T+10 -execute /bin/sleep 90; touch X
~50	scheduler polls, sees new entry; fire time (T+10) is 40s in the past → "wait until tomorrow"
10..end	my _wait(...) loops on the marker file. Times out.

The scheduler log even looked healthy:

Adding job at 20:15:52 -execute /bin/sh -c '/bin/sleep 90; ...'
job 0 fire=72952 type=EXECUTE ...

Reading those, I thought the job was queued. It was queued — for
tomorrow (72952 seconds since midnight = 20:15:52 the next day).

Root cause. Polling introduces a hidden discrete-time boundary
between "install" and "first evaluation". Any entry whose fire time
falls inside that boundary is silently rerouted through the past-time
branch. The branch has no log signal for "this entry got rescheduled
because you installed it too late."

Escape recipes.

# WRONG — racy with the polling boundary
fire_at = now + 10

# RIGHT — guaranteed to fall in the FIRST polling window after install
fire_at = now + N + slack       # slack ≥ 30s to absorb fixture timing

For wait timeouts:

# Cover: next poll (≤ N) + fire delay (N + slack) + job runtime
timeout = 2 * N + slack + job_runtime

Extra guard. After writing the config, assert the fire time is in
the future from the scheduler's perspective (i.e. from a fresh
date on the target host, not from the test-runner's clock). A
one-line guard catches misconfiguration before the wait swallows it.

Where else this bites. Cron-like systems with poll interval, DB-
mtime-polled app-server config, file-watcher debouncers, etcd/K8s
watch-with-resync intervals, distributed job schedulers using
mtime-tick to detect config changes. Whenever you see "polling
interval = N" in the spec, your test inputs need > N + slack.

Note. This is a special case of pattern 2 — the "filter" is the
past-time gate, the empty result is "marker never appears", and the
fix is the same: verify with an independent observation
(ssh + tail of the scheduler's own log) before trusting your test
predicate's silence.

---

4. Monotonic identity

Trap. You're writing a fault-injection or recovery test. You need to
assert that after the injection, the system "recovered to the same
state." You reach for the identifier that's easiest to observe — PID,
listening port, cmdline, IP:port four-tuple, process count. Test
passes. Test is vacuous.

Concrete failure I hit. A session-preservation test on a session
manager. Fault: burst-reset all its client sockets. Post-fault gate:
"count of active sessions unchanged."

Passed. Repeatedly. Then a review pass caught that the session manager
was keeping session-id rows in its table long after the owning TCP
socket died — a ~90-second batch-sweeper cycle, not per-session TTL.
So during the fault, sessions were logically dead (the client gRPC
stream was broken, the next request would be rejected as "invalid
session id"), but the count stayed the same because the rows hadn't
been reaped yet. A user staring at the UI got locked out. My test said
green.

Fix: swap the count-based gate for session-id set preservation —
snapshot the baseline set of session ids before the fault, assert the
post-fault set is a superset. Session ids are never reused, so set
membership = identity preservation. Every fault-injection test in the
suite grew this gate. Several latent bugs that had been passing for
months surfaced immediately.

Root cause. Two different kinds of identifier:

• Spatial — names what's there now. PID, IP, listening port, four-tuple, cmdline, file path, resource count. Reused: the same value can name entity X at t1 and entity Y at t2. Describes a snapshot.
• Temporal / monotonic — names which event. session id, epoch, term, generation, LSN, offset, fencing token, revision. Never reused. Describes a moment in history.

Recovery tests must assert across time ("post state contains
baseline state"). Spatial identifiers can't carry that assertion —
they only describe now. Monotonic identifiers can.

How spatial identifiers betray you.

• PID reuse — parent dies, restarts; new PID can be smaller than old (PID counter wrap). Fork may hit a released PID with identical cmdline. pid_changed and pid_same both lie.
• Port-listen ≠ working — a service binds its socket the moment listen() returns, but internal state (open segments, DB attach, cache warmup) can be minutes behind. ss -lnt says green; next request rejected. The classic "startup completed = healthy" trap.
• cmdline is just a string — parent and child service managers often share exact cmdline. Only PPID or start time disambiguates. Falling back to "the PID with smaller start time" is fragile under restart.

The monotonic-identity zoo (patterns to recognize across systems):

Identifier	Allocator	Where it lives
session id	server at login	web sessions
epoch / term	leader election	Raft, Kafka controller
generation number	restart event	GFS chunk version, ZK zxid high
LSN / offset	per write	Postgres WAL, Kafka partition
fencing token	lock service	Chubby, etcd lease
logical clock	per event	Lamport, vector clock
revision / version	watch cursor	etcd revision, ZK zxid

Common shape: monotonic + never reused. Distinguishing epoch 5 from
epoch 6 needs no other context.

Three reflex questions. When reviewing recovery / reconnect /
failover / idempotency code:

1. What identity is being used to mean "same thing"?
2. Can it be reused? Even in a narrow window?
3. If the peer restarted / network flapped / clock jumped, does the judgement still hold? "Depends on luck" → upgrade to monotonic.

Where this transfers.

• Reconnect protocols — client_id (monotonic) survives IP changes; four-tuple loses identity every reconnect. Stripe's idempotency key is the same idea.
• Leader election — Raft term is the textbook. Without it, split-brain detection by hostname is unsafe.
• Distributed locks — Kleppmann's How to do distributed locking attacks Redlock exactly because it lacks fencing tokens: a GC-paused holder writes with a stale token → storage rejects → safe.
• DB replication — Postgres LSN, MySQL GTID. "Replicated through transaction #1000" lies on retry; "through LSN=X" doesn't.
• Message queue consumers — Kafka offset commits are monotonic; cursorless long-polling drops events on reconnect.
• Watch APIs — etcd/ZK watch resume by revision; without the cursor, events between disconnect and reconnect vanish silently.

Implementation pattern.

# Spatial (fragile)
assert post_pid == baseline_pid

# Temporal (sound)
baseline_ids = snapshot_session_ids()
inject_fault()
assert_ids_preserved(baseline_ids)

---

The unifying shape

All four are variations on "my observation channel is lying to me,
and I don't know it."

Pattern	What lies	Independent check
Cumulative log	grep reads history as state	Nonce / offset / truncate
Silent filter miss	Filter empty ≠ target absent	Second observation channel
Polling-fire window	Install-log looks successful	Assert fire time is future, from target's clock
Monotonic identity	Spatial ids look preserved	Set-membership of never-reused ids

The escape is the same shape every time: before publishing a claim,
have a second independent channel confirm it. Different query axis,
different tool, different observer. Two channels agree → high
confidence. One channel and a plausible story → almost certainly
wrong.

This is the QA-side version of "don't trust a single monitor": the
same discipline SREs apply to production observability, applied to
test observability.

---

Companion practice: self-question before archiving

The four patterns above are trigger-specific. There's a fifth,
higher-level habit that catches the same class of errors when you
don't know which trigger applies:

Before archiving any evidence-heavy result — a baseline, a
diagnosis, a "this test suite is complete" claim — spend 15–30
minutes on a structured skeptical pass.

For every load-bearing claim in the write-up:

1. Name the specific query that would break it. Off-by-one in a range filter. Aggregation granularity too coarse. Missing a source. Cherry-picked window.
2. Time-bucket log evidence at the granularity the claim needs. "Zero errors during steady state" is not verifiable at minute granularity if the run ends mid-minute; bucket at seconds around the transition points.
3. Cross-reference independent data sources. Client-side failures vs server-side errors vs downstream cleanup counts — three views of the same event; if they disagree, the headline claim is soft.
4. When a claim survives, keep it. When it doesn't, downgrade it in the archive itself. "No leak" → "no leak signal at 200 users; 400 users +9 fd in final 2 min inconclusive." Downgrades live in the evidence, not in a follow-up note.

A recent 30-minute pass on a performance baseline caught three real
problems using exactly this loop: an "fd flat" claim that was true at
one load level but not at another, a "reaper cleaned N orphans" claim
where the reaped set had zero overlap with the failed set, and a "N
server errors = mix of noise + shutdown race" claim where the
uptime-conditioned noise source couldn't have produced any of them.

None of those would have surfaced from re-reading the summary. They
came from re-running the queries at tighter buckets and against
cohorts the summary hadn't cross-checked.

The habit is cheap and catches errors that would otherwise ship.