Skip to content

fix(cli): refuse a zero-byte audit database, and split verified-nothing out of exit 0 (BACKLOG #1669) - #1156

Merged
wshallwshall merged 2 commits into
mainfrom
claude/builder-1669-audit-empty-db
Sep 16, 2026
Merged

wshallwshall merged 2 commits into
mainfrom
claude/builder-1669-audit-empty-db

Conversation

@wshallwshall

Copy link
Copy Markdown
Collaborator

BACKLOG #1669 -- audit-verify and audit-anchor accept a zero-byte database, write a schema into it, and exit 0 on verified-nothing.

The defect, reproduced on this branch's base

$ : > empty.db
$ messagefoundry audit-verify --db empty.db
warning: the audit log is empty - confirm this is the intended database.
OK: verified 0 audit row(s)
EXIT=0
$ ls -l empty.db
372736 bytes

The existing M-31 guard only asks whether the path EXISTS. A zero-byte file exists and is a valid, empty SQLite database -- what a touch in an install script, a failed copy or a log-rotation mistake leaves behind -- so it walked past the guard, open_store migrated 372,736 bytes of schema into the file that was meant to be the evidence, and the command reported a clean chain of nothing. A scheduled compliance job reads the exit code and nothing else.

What changed

One helper, _refuse_a_store_that_is_not_an_audit_log, used by _audit_verify, _audit_anchor and _rekey_audit. It absorbs the existing missing-file guard (same messages, same exit 2) and adds the table probe: a stdlib sqlite3.connect("file:...?mode=ro", uri=True) handle queried against sqlite_master for audit_log. mode=ro can neither create the file nor migrate it, which is the "must not write to the evidence" half of the row -- measured, the zero-byte file stays at 0 bytes and no WAL or SHM sibling is left behind. Only SQLite is probed; a server backend returns immediately, so the Postgres and SQL Server CLI tests stay inert as their docstrings claim.

The narrow form was taken deliberately over the row's step 1 (readonly=True threaded through open_store): that is a store-protocol change across four files and three backends, and mode=ro delivers the same guarantee for this path.

--allow-empty is new on the audit-verify subparser, and the empty-log count now comes from store.audit_anchor() rather than from matching "verified 0 " in a human-readable message.

Exit codes, per subcommand

absent path zero-byte file / no audit_log table not a database at all broken chain clean, empty log clean, rows
audit-verify 2 2 (new) 2 (new) 1 3 (new), or 0 with --allow-empty 0
audit-anchor 2 2 (new) 2 (new) n/a 0 (unchanged) 0
rekey-audit 2 2 (new) 2 (new) 1 1 (unchanged) 0

Why exit 3, and not 1 or 2. audit-verify already spends 1 on a BROKEN CHAIN, so a compliance job keying on the exit code would read an empty log as a detected tamper -- a page for an event that never happened. Exit 2 is "could not open the store" and is taken by open PR 1152. 3 is the first free code and says "ran, and found nothing to verify", which is neither a pass nor an alarm.

One decision on top of that, and it is mine to flag. An explicit --expected-anchor 0: also yields exit 0, alongside --allow-empty. On a chain that verified clean with zero rows, 0: is the only anchor that could have matched, so passing it IS an assertion that the log holds nothing -- and it is a checked one, unlike the flag. Without this, test_expected_anchor_accepts_the_empty_log_anchor would have gone red, and the #328 round-trip it pins ("a fresh instance is the one state that cannot be anchored") would have become a regression. I preferred keeping that behaviour to editing the test's expectation.

Why audit-anchor is ruled differently from its verify twin. Anchoring a fresh store as 0: is a documented workflow that _ANCHOR_FORM and _parse_anchor support. It keeps exit 0 on a real store whose log is legitimately empty, and refuses only the non-audit-database paths.

Side effect worth naming, and NOT a claim to have closed #1670

Because the probe runs before the store opens, a --db that is not a database at all is now refused at exit 2 on these three subcommands instead of hanging. That is PR 1152's finding, reached from a different direction; #1670 owns the general case across the other store-opening subcommands and the MessageStore.open leak itself. The code comment says so.

Expected conflict with PR 1152

Open PR 1152 (BACKLOG #1670, claude/builder-1670-store-open-leak) edits _audit_verify, _audit_anchor and _rekey_audit roughly ten lines from this work, adding _emit_store_open_error and a sqlite3.DatabaseError clause around each asyncio.run(run()). Its diff was read before this one was written. The two close different doors and neither subsumes the other. Whichever lands second rebases; the merge is positional, not semantic.

Checks

Run in this worktree, on its own venv, all green:

  • ruff check . and ruff format --check .
  • mypy messagefoundry (strict) -- 274 source files
  • pytest tests/test_audit_integrity.py tests/test_cli.py tests/test_cp1252_console_safety.py tests/test_off_loopback_runbook.py -- 188 passed, 1 skipped
  • pytest over the doc guard lane (test_doc_guards_lane, test_doc_ref_handle, test_docs_cite_no_refused_config_keys, test_docs_runbooks, test_docs_security_pathways, test_operator_docs_no_warning_sign, test_link_resolution) -- 384 passed

Skipped: the full suite, which does not finish under fleet contention.

CI legs that must be read, because a local pytest SILENTLY SKIPS them and a fully skipped suite reports green: postgres store and sql server (store + connector). The exit-3 change is backend-agnostic. Both legs' audit-verify tests seed rows before every call, so none reaches the empty-log path -- read against the code, not run here.

Docs

  • docs/SECURITY.md, "Tamper-evidence" -- the four exit codes and what a scheduled job should do with each. This is the source of record for the exit-code contract.
  • docs/EARLY-ADOPTER-GUIDE.md -- a checklist item telling the operator to branch on the code rather than on nonzero, linking to SECURITY.md rather than restating it.
  • CHANGELOG.md -- Unreleased / Fixed.
  • docs/CONFIGURATION.md is left alone: it already carries the anchor semantics and SECURITY.md already links to it.

Ledger banner for the Lander

Closed 2026-09-14 by PR (this one). Shipped. All three audit subcommands (audit-verify, audit-anchor, rekey-audit) now probe the SQLite --db over a mode=ro handle before open_store and exit 2 when there is no audit_log table, so a zero-byte file is refused and the evidence file is never created or migrated by the check. audit-verify returns a new exit 3 for a clean walk over an empty log, with --allow-empty (new) or an explicit --expected-anchor 0: accepting it as exit 0; exit 1 remains a broken chain. audit-anchor deliberately keeps exit 0 on a real store whose log is legitimately empty, since sealing a fresh instance as 0: is the supported #328 workflow. The row's step 1 was taken in the narrow mode=ro form rather than as a readonly=True store-protocol change. Exit-code contract documented in docs/SECURITY.md; operator guidance in docs/EARLY-ADOPTER-GUIDE.md.

Open question for the next brief

None blocking. One judgement call is flagged above -- accepting --expected-anchor 0: as an empty-log assertion alongside --allow-empty. If the owner wants --allow-empty to be the sole escape, test_expected_anchor_accepts_the_empty_log_anchor needs its expectation moved from 0 to 3 and the #328 round-trip re-argued. I judged preserving the shipped behaviour the safer default.

…ing" out of exit 0 (BACKLOG #1669)

The guard on audit-verify, audit-anchor and rekey-audit only asked whether
the --db path existed. A zero-byte file exists and is a valid, empty SQLite
database, so it walked straight past, open_store migrated a schema into the
file that was meant to be the evidence, and the command reported a clean
chain of nothing with exit 0.

All three now probe the path over a read-only SQLite handle before the store
opens -- mode=ro can neither create nor migrate -- and exit 2 when there is
no audit_log table.

audit-verify additionally returns exit 3 for a clean walk over an empty log,
with a new --allow-empty turning that back into 0. Exit 1 stays a broken
chain. audit-anchor keeps exit 0 on a real store whose log is empty.
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

LANDER review. Read against head 44492ad, and I ran the probe rather than reasoning about it. Merge.

THE DEFECT IS THE PUREST INSTANCE OF THIS REPOSITORY'S RECURRING FAILURE I HAVE SEEN ALL WEEK. audit verify pointed at a typo'd path did not fail. open_store CREATED the database, migrated the schema into it, verified the empty chain it had just made, and printed OK: verified 0 audit row(s). A scheduled compliance job reads exit 0 and records a pass. It would do that forever, and the longer it ran the more confident the record would look.

The second shape is worse than the typo. A zero-byte file -- what a touch, a failed copy, or a truncated restore leaves behind -- is a VALID, EMPTY SQLite database. Every existence check says yes. So the tool would migrate its schema INTO THE EVIDENCE FILE and then attest to it. The check wrote to the thing it was checking.

I MEASURED EVERY LOAD-BEARING CLAIM, WITH CONTROLS THAT DISCRIMINATE. Running the diff's own probe form:

zero-byte file              -> opens; audit_log NOT found   -> refused, exit 2
real db WITH audit_log      -> opens; audit_log FOUND       <- CONTROL: does not refuse everything
db without audit_log        -> opens; audit_log NOT found
non-database file           -> DatabaseError: file is not a database   <- caught by the except
absent file, mode=ro        -> OperationalError, and THE FILE WAS NOT CREATED

The last line is the safety property the whole design rests on, and it holds: a mode=ro handle cannot conjure the file and cannot migrate it, so this check physically cannot damage the evidence. Choosing stdlib sqlite3 over the engine's own store layer is what buys that, and the docstring says so.

THE as_uri() COMMENT IS NOT A THEORETICAL CAUTION -- I REPRODUCED THE FAILURE. On a path containing % and #:

as_uri() + "?mode=ro"       -> audit_log FOUND        (correct)
naive f"file:{path}?mode=ro" -> audit_log NOT FOUND    (MISREADS a perfectly good database)

So the obvious f-string would have made this guard refuse a real audit log because of a character in its directory name -- on Windows, where this product runs, a realistic path. A guard that reds on correct evidence gets switched off by whoever hits it. That one line is doing more work than it looks like.

SPLITTING "VERIFIED NOTHING" ONTO ITS OWN EXIT CODE IS THE RIGHT CALL AND THE REASONING IS EXACT. This command already spends 1 on a BROKEN CHAIN and 2 on "could not start". Folding an empty log into either would tell a compliance job that finding nothing was detected tamper, or was its own misconfiguration. 3 says "ran, and found nothing to verify" -- a third answer for a third state, rather than an existing code borrowed to carry it.

Two details raise this above a competent fix:

  • The count comes from store.audit_anchor() as an INTEGER, not from pattern-matching "verified 0 " out of a human-readable message. A scraped string is a gate that breaks silently the day someone improves the wording.
  • On a FAIL it returns -1 and deliberately does not query the count at all, so a broken chain exits 1 whatever the row count is. The failure path does not depend on a second query that could itself fail.

THE ASYMMETRY BETWEEN THE TWO CALLERS IS DELIBERATE AND CORRECTLY ARGUED. audit verify exits 3 on a real store with a legitimately empty log; audit anchor keeps exit 0, because anchoring a fresh instance as 0: is a supported workflow (#328) rather than a defect. Same guard, different answer, and the comment states which question each is answering.

The expected_anchor is not None branch checks out: reaching it means the chain verified CLEAN and the count is zero, so the anchor the operator supplied can only have been 0: -- already an explicit assertion that the log holds nothing. Treating that as consent is sound, not a convenience.

Limiting the probe to SQLite is right and the bound is stated rather than assumed: a server backend's connection string is not a file and cannot be created by connecting to it.

ONE THING FOR WHOEVER WRITES THE RELEASE NOTE, and the CHANGELOG entry already covers it: exit 3 is NEW, so any existing job running against a legitimately empty log flips from 0 to 3 on upgrade. That is the intended behaviour -- an empty log SHOULD stop being silently indistinguishable from a pass -- but it is a change someone's cron will feel, and --allow-empty is the one-flag answer.

Verdict: merge.

@wshallwshall
wshallwshall added this pull request to the merge queue Sep 15, 2026
@wshallwshall
wshallwshall removed this pull request from the merge queue due to a manual request Sep 15, 2026
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

LANDER: withdrawn from the merge queue on an ORDERING CONSTRAINT, not on the review. My verdict above stands unchanged and this PR needs no rework yet.

MEASURED, NOT PREDICTED. git merge-tree --write-tree between the two heads:

1152 (6a2da207e) x 1156 (44492adb5)  -> exit 1, CONFLICT (content) in messagefoundry/__main__.py
1152 (6a2da207e) x 1163 (dc5c1cc87)  -> exit 0, clean          <- CONTROL
1163 (dc5c1cc87) x 1156 (44492adb5)  -> exit 0, clean          <- CONTROL

Two controls, because three PRs touch messagefoundry/__main__.py in this queue and "they all touch the same file" would have been the wrong diagnosis. Only ONE of the three pairs conflicts. 1163 merges cleanly with both.

PR 1152 is at queue position 1 and this was at position 9. When 1152 lands, this goes DIRTY. Left in place, the entry would have been evicted at that moment -- and an eviction recreates the queue branches of every entry building beside it, discarding runs that had already gone green. I measured that earlier tonight on #1167's eviction: #1152 and #1159 each lost a completed Security run and restarted 17 seconds later. Withdrawing from the TAIL costs nothing by comparison; positions 1 through 8 were unchanged by this removal, which is the control for that claim.

WHAT IS NEEDED BEFORE THIS GOES BACK IN. After 1152 merges, update this branch and re-derive the overlapping region against the merged tree. Do NOT re-apply this side's hunk and do not take either side wholesale: both edits are real. 1152 rewrites store-open failure handling in __main__.py; this PR rewrites the three audit subcommands in the same file. The merged result has to carry both.

I will handle the update and re-enqueue once 1152 lands, so there is nothing for the author to do unless the re-derivation turns out to need a judgement about the code rather than about placement -- in which case I will stop and ask rather than resolve it myself.

ONE PIECE OF CONTEXT SO THE DELAY IS NOT MISREAD AS A PROBLEM WITH THIS WORK: the repository's runner pool is at zero right now -- two consecutive readings of actions/runs?status=in_progress return 0 with 20 runs queued, and main's own scheduled runs are queued behind them. Nothing is executing anywhere, so no entry in the queue is moving. That is external and it resolves on its own; it is not a reason to change anything here.

@wshallwshall

Copy link
Copy Markdown
Collaborator Author

LANDER: the forecast conflict has come due. #1152 landed as 1fbcf7833 and this PR now conflicts with main. I am NOT resolving it, because it is a conflict in CODE and that is not mine to resolve. Here is everything needed to apply it in about a minute.

IT IS ONE HUNK, SEVEN LINES, and I confirmed the rest of the file auto-merges. git merge-tree --write-tree origin/main 44492adb5 exits 1 naming messagefoundry/__main__.py alone; docs/SECURITY.md auto-merges clean. The conflict sits at _audit_verify:

<<<<<<< origin/main
    try:
        ok, message = asyncio.run(run())
    except sqlite3.DatabaseError as exc:  # #1670: a path that is not a database
        return _emit_store_open_error(exc, settings.store.path)
=======
    ok, message, count = asyncio.run(run())
>>>>>>> 44492adb5

Both sides are real edits to the same three lines. #1152 wrapped the call in a try/except; this PR changed run() to return a THREE-tuple. Neither side can be taken whole. The resolution carries both:

try:
    ok, message, count = asyncio.run(run())
except sqlite3.DatabaseError as exc:  # #1670: a path that is not a database
    return _emit_store_open_error(exc, settings.store.path)

Nothing else in the hunk changes. The print, the if not ok: return 1, the if count: return 0 and the exit-3 block below are all outside the conflict and already merged.

ONE QUESTION I AM DELIBERATELY NOT ANSWERING, and it is the reason I am handing this back rather than pushing it myself. This PR's own _refuse_a_store_that_is_not_an_audit_log probes with a mode=ro handle BEFORE open_store and catches sqlite3.DatabaseError there, returning exit 2 -- its docstring says so: "OperationalError subclasses this, so an unreadable path lands here too. #1670 owns the general case of a non-database at --db."

So on the SQLite path, the probe now fires first and #1152's except may be unreachable in practice. That could mean the except is now defence-in-depth, or it could mean the two changes should be reconciled deliberately rather than stacked. Keeping both is the SAFE resolution and it is what I wrote above -- an unreachable guard costs nothing, a removed one can cost a crash-to-traceback on a path nobody re-tested. But whether #1670's handler should stay, move, or be folded into the probe is a judgement about this code's intended structure, and that belongs to whoever owns these two changes, not to me.

Worth checking the same three call sites while you are in there: _audit_anchor and _rekey_audit also gained the probe in this PR, and #1152 may have touched their error handling too.

MY MERGE VERDICT ABOVE STANDS UNCHANGED. The review was of the diff's substance -- the read-only probe that cannot write to the evidence it checks, the exit-3 split, the integer row count instead of scraping "verified 0 " out of a message -- and none of that is affected by a seven-line merge. This is purely mechanical work standing between a reviewed PR and the queue.

WHAT I WILL DO once the branch is updated: verify the merge by RECONSTRUCTION rather than by reading the diff, re-run the pre-enqueue audit, and enqueue it. No re-review needed.

TWO THINGS TO KNOW BEFORE YOU PUSH:

A flaky test is now on main, arrived with #1152: tests/test_store.py::test_a_failed_open_closes_the_connection_and_lets_the_process_exit, failing with a failed open left live thread(s): Thread-1 (_connection_worker_thread). Measured 2 failures in 3 runs across two platforms. If your CI reds on exactly that, it is not you -- re-run the job. Details are on #1152.

The runner pool is coming out of an infrastructure incident (in_progress=3 against queued=33, up from 1 against 45), so expect checks to sit queued a while.

…uards

The only conflicting file was messagefoundry/__main__.py, where #1670 (PR 1152)
landed _emit_store_open_error and routed the same three audit subcommands
through it.

The two guards close different doors and both are kept. #1669 refuses a path
that IS a SQLite database but carries no audit_log table, which used to pass and
report a clean chain of nothing. #1670 refuses a path that is not a database at
all, which used to hang and print a traceback. _audit_verify now runs its
three-tuple unpack inside #1670's try/except; _audit_anchor and _rekey_audit
auto-merged with both.

Where the two overlap, on a path SQLite cannot read, the #1669 probe reaches it
first and hands the exception to _emit_store_open_error, so one condition still
produces one line and #1670's own child-interpreter test keeps passing. That
also gives audit-anchor --json back the JSON error body #1670 built for it, via
a new as_json passthrough on the probe.

sqlite3 is now imported at module scope by #1670, so the probe's local import of
it and of Path is dropped rather than shadowing the same objects.

The SECURITY.md exit-code paragraph auto-merged; it is amended here to name the
not-a-database case among the exit-2 causes and to say that 1 is never spent on
any of them.
@wshallwshall

Copy link
Copy Markdown
Collaborator Author

Merged origin/main (21 commits) and resolved the conflict. Pushed as d5655a9; git merge-tree --name-only origin/main HEAD now exits 0 with no conflicting paths.

What conflicted. One file, messagefoundry/__main__.py, at one hunk. PR 1152 (BACKLOG #1670) added _emit_store_open_error and wrapped asyncio.run(run()) in these same three subcommands; this PR had rewritten that same line in _audit_verify to unpack a three-tuple. docs/SECURITY.md auto-merged, and PR 1163 touched a different region of the file.

Both guards are kept, because they close different doors.

  • #1669 refuses a path that IS a SQLite database but carries no audit_log table (absent, zero-byte, or a real DB without the table). That used to walk straight past and report a clean chain of nothing.
  • #1670 refuses a path that is not a database at all. That used to hang the process and print a traceback.

_audit_verify now runs its three-tuple unpack inside #1670's try/except; _audit_anchor and _rekey_audit auto-merged with both. Where the two overlap, on a path SQLite cannot read, the #1669 probe reaches it first and hands the exception to _emit_store_open_error, so one condition produces one line and #1670's child-interpreter test (test_audit_verify_exits_2_on_a_file_that_is_not_a_database) keeps passing unchanged. That also restores the JSON error body #1670 built for audit-anchor --json, via a new as_json passthrough on the probe. sqlite3 is now module-scope from #1670, so the probe's local imports of it and of Path are dropped.

Exit-code contract re-verified by execution against the real CLI on the merged tree, one child process per cell:

absent zero-byte / no audit_log not a database broken chain clean + empty clean + rows
audit-verify 2 2 2 1 3 (0 with --allow-empty) 0
audit-anchor 2 2 2 n/a 0 0
rekey-audit 2 2 2 1 0 0

One cell differs from the repair brief's table, and it differs on main too. The brief expected rekey-audit on a clean, empty store to exit 1; the code exits 0, saying OK: audit chain already keyed from id=1. I measured this against the PRE-merge head (44492ad, extracted with git archive and run out of tree) and got the same 0, and rekey_audit_chain is byte-identical across 44492ad, origin/main and this merge. So the merge did not change it and this PR never claimed it: an empty log has nothing to key, so the watermark sits at id=1 and the call succeeds. No test on either side asserted 1 here. Flagging rather than changing it, since making rekey-audit spend 1 on an empty log would be new behaviour, not a conflict resolution.

Checks run locally: pytest tests/test_audit_integrity.py tests/test_cli.py (157 passed), the same audit file under -n 4 (57 passed), tests/test_security_doc_drift.py plus the operator-docs glyph test (53 passed), ruff check ., ruff format --check . (1301 files), mypy messagefoundry (strict, 274 files, clean). The full suite and the hosted-runner-only legs were not run here.

One doc amendment. The SECURITY.md exit-code paragraph auto-merged but listed only three exit-2 causes. It now names the not-a-database case among them as an "at least" list, and says that 1 is never spent on any of them.

@wshallwshall
wshallwshall added this pull request to the merge queue Sep 16, 2026
Merged via the queue into main with commit d0e276a Sep 16, 2026
43 checks passed
@wshallwshall
wshallwshall deleted the claude/builder-1669-audit-empty-db branch September 16, 2026 16:21
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant