My Daemon Dropped 1,000 Records and Reported Success

A soak test came back green. Chain intact, verify-store fine, p99 latency 0.36 ms. Then I counted the rows: 9,016 out of 10,000. About a thousand records had gone missing, and every caller had been told the write succeeded.

This is the kind of failure that a background thread holding a lock the hot path needs produces — and raising a buffer to "fix" it is the wrong first move.

Two threads, one lock

The agentwatch recorder daemon — one tool in agentic-suite, a suite of open-source, harness-agnostic security tools for AI agents — has two threads that matter.

Thread 1 — Accept (the hot path): accepts Unix socket connections from hooks, reads the message, normalizes it, appends it to the hash-chained store.

def _append(self, record):
    with self._lock:            # ← needs store._lock
        self.store.append(record)

Thread 2 — Sweeper (background verification): every 5 seconds, reloads the store from disk and re-verifies the entire hash chain. This is continuous verification — if someone tampers with the store file mid-session, the sweeper detects it and flips health to degraded.

def _sweep_loop(self):
    while not self._stop.wait(5.0):
        self.chain_status = self.store.refresh()   # ← the problem

Both threads need store._lock. And refresh() was greedy about it:

def refresh(self):
    with self._lock:
        self._entries = self._load()   # read the ENTIRE file from disk
        self._recount()
        return self.verify()           # recompute EVERY hash — O(n)

Reading the file and rehashing the chain, start to finish, with the lock held the whole time. At small scale this is invisible — and that's exactly why it survives into a soak test.

What that cost

At a thousand entries it's nothing. Eleven milliseconds. At five thousand, fifty-six. At ten thousand, about a hundred and sixteen. By the end of a 10k-send soak the store held around twenty thousand entries, and a single sweep took 242 milliseconds.

Here's what happens during those 242 ms:

1. The sweeper acquires store._lock.
2. It reads the entire store file from disk (_load()).
3. It recomputes every hash in the chain (verify() — O(n)).
4. Meanwhile, the accept thread tries to append(). It blocks on store._lock.
5. New hook connections queue in the listen backlog (512 slots).
6. At ~200 records/sec, ~48 appends queue during the 242 ms lock hold.
7. If the backlog fills before the sweeper releases, send() connects time out (1 s timeout).
8. send() returns False. The hook is fire-and-forget — the agent doesn't retry. The record is lost.

Over 100 seconds of soak, the sweeper runs 20 times (every 5 s). Each sweep blocks ~48 appends. 20 × 48 = 960 blocked appends. 9,036 of 10,000 delivered. 964 silently lost.

The agent doesn't know. send() returns False, but the hook is fire-and-forget — the agent ignores the return value. The daemon doesn't log the dropped sends. The store has 9,036 records instead of 10,000, and the only way to notice is to count.

The fix that wasn't a fix

The first diagnosis was wrong, and it cost two full test runs.

"The single-threaded accept path is the bottleneck." The listen backlog was 128, so it got raised:

# Before
server.listen(128)

# After
server.listen(512)

Result: 9,499/10,000 (95%). Better. Still dropping 500.

The first run before any backlog change was 9,016/10,000 (90%). Raising to 512 moved it to 9,499 (95%). The improvement was real but the problem was unchanged — more queue room just meant more sends waited longer before timing out. The drop rate went from 10% to 5%, but 500 records still vanished.

The diagnosis was "the accept path can't keep up." The actual problem was "the accept path is blocked." Those look the same from the outside — sends are being dropped — but the fix is completely different. The first says "make the accept path faster or give it more room." The second says "stop holding the lock it needs."

Because more backlog doesn't prevent drops — it delays them. The bottleneck was never queue capacity. It was the time append() spent blocked on the lock. More backlog means more sends queue before timing out, but they still time out if the sweeper holds the lock long enough.

tip: Raising a backlog, pool size, or buffer to "fix" a performance issue is usually a band-aid. If the bottleneck is lock-hold time, more queue room just delays the drops. Measure the lock-hold time before you touch the queue.

Two full suite runs went to a band-aid before the actual lock got measured.

The right fix: snapshot, then verify

Move the expensive work out of the critical section. Read and verify without the lock, then swap the in-memory reference under the lock — O(1):

def refresh(self):
    entries = self._load()                  # disk read — no lock
    status = self._verify_entries(entries)  # O(n) verify — no lock

    with self._lock:                        # O(1) reference swap
        if len(entries) >= len(self._entries):
            self._entries = entries
        self._recount()
    return status

The lock now covers a pointer assignment instead of 242 ms of work. The accept thread never blocks for more than microseconds.

tip: Never hold a lock the hot path needs while doing O(n) work. Snapshot under the lock, process outside it, swap the reference in O(1). The work doesn't get faster — the critical section gets 242 ms smaller.

Result: 10,000/10,000 delivered. p99 = 0.36 ms. verify-store green.

The second bug the fix introduced

The very next run after that change failed:

agentsec-agentwatch: chain broken at seq 815

Moving the read outside the lock introduced a race. The disk read (_load()) runs without the lock. While it's reading, append() may write new entries to the file. The disk read can complete before those writes land, producing a shorter entry list — 815 entries instead of 820.

If refresh() then replaces self._entries with this shorter list, the next append() computes seq = 815 + 1 = 816 and prev_hash = entries[815].hash. But entry 816 was already written to disk by the append() that happened during the disk read. Now there are two entries with seq 816 on disk. The chain is broken.

The fix is the length guard:

if len(entries) >= len(self._entries):   # never adopt a stale, shorter snapshot
    self._entries = entries

If the disk snapshot is shorter than what's in memory, keep memory. Verification still runs on the snapshot — and may detect tampering — but the in-memory state is not corrupted. The next sweep picks up whatever it missed.

This is the subtle cost of moving work outside a lock. When the lock protected both the read and the swap, the snapshot was always consistent with memory by construction. When the read happens unlocked, the snapshot can be stale — and "stale" means "shorter than reality" in an append-only store. The length guard turns a potential chain break into a benign missed sweep.

The scaling table

The total refresh() time is the same — the file read and verification still take O(n). What changed is what is locked:

Store entries	refresh() total time	Lock held for
1,000	11 ms	~0 ms (reference swap)
5,000	56 ms	~0 ms
10,000	116 ms	~0 ms
20,000	242 ms	~0 ms

The work didn't get faster. The critical section got 242 ms smaller.

What I keep repeating to myself

O(n) under a contended lock is a scaling cliff. It works at low n, fails at high n, and fails silently and load-dependently — invisible in unit tests, visible only under sustained load.

Silent data loss is worse than a crash. A crash is visible. A dropped record with a success response is a lie the operator can't see. At least a crash tells you something broke.

The symptom doesn't point at the cause. "Sends are being dropped" sends you to the network, the backlog, the accept loop. The real cause was lock contention in a background thread. Per-thread timing is what diagnoses it.

It's fixed in agentwatch v0.1.0, and the 10k soak is the regression test that keeps it fixed.

The question worth asking of your own system: what's the lock-hold time of your background work at 10× your current scale? If it hasn't been measured, it's probably the thing blocking the hot path.

References

• Release: agentwatch v0.1.0 on GitHub · on PyPI
• Suite: agentic-suite — the full set of agent-security tools
• Field test report (defect D-1, FT-28)
• Soak evidence: FT-28/
• Store: store.py

Comments

[Kent Bodrov]

Could you separate blocked appends, timed-out send attempts and records missing at the end in the soak report? The 20 × 48 estimate counts work arriving during lock holds, but those appends need not all be lost: some can drain after the lock releases. Also, the post says both that callers were told success and that send() returned False and the hook ignored it. Showing the result at each boundary would make the loss mechanism much easier to reproduce than inferring drops from lock duration alone.