BACKLOG #1197: measure the ASVS 16.3.2 audit-flood cost, and correct the row's stale premise

[wshallwshall]

BACKLOG #1197 -- ASVS 16.3.2: the audit-flood cost, measured

This item exists because an explicit ASVS "must" was traded against a flooding cost that ADR 0118 section 5 and the audit_all_authz field comment both assert and neither measures. This PR is that measurement, plus the two reading questions the item pairs with it. It changes no product behaviour: one new test module and one BACKLOG row.

The row's premise is stale, and it fails in the direction that makes the gap look wider

Verified by symbol at HEAD before building on it, which the brief asked for and which paid off:

Row says	At HEAD
audit_all_authorization_decisions ships False	ships True -- BACKLOG #1277 flipped it, ADR 0118 section 5 carries the amendment
a GET records no grant row	a GET does -- require's guard is if audit_all or request.method != "GET"
non-GET only for the 15 in _GRANT_AUDIT_PERMISSIONS	the set still holds 15, but it governs only the switch-off posture

What survives is the severity sentence's core: require calls audit_permission_denied inside the permission loop, above the audit_all read, so denials are recorded in every configuration. No exposure is at stake anywhere in this PR.

(a) The measurement

Command:

QT_QPA_PLATFORM=offscreen pytest packaging/messagefoundry-webconsole/tests/test_authz_audit_rate.py -q -s

Arm	What is running	Requests/min	Audit rows/min	Rows/day
A	HEAD as shipped -- tab on any page	6	0	0
A	HEAD as shipped -- connections dashboard	18	0	0
A	HEAD as shipped -- flow page	18	0	0
B	proposed console grant parity -- any page	6	4	5,760
B	proposed console grant parity -- connections dashboard	18	16	23,040
B	proposed console grant parity -- flow page	18	16	23,040
C	JSON API on the shipped default -- one harness monitor	120	120	172,800

Method. Rows per minute is a quotient of two exactly-known integers, so no number is a timing sample. The numerator is measured against the real ASGI app, a real AuthService, a real store and the real hash-chained audit_log, driven over a real /ui cookie session. The denominator is derived by regex from the console's own source and compared against the table the arithmetic uses, so editing one copy cannot silently rescale a published rate. ARM C reads both its interval and its call set out of harness/monitor.py, so a fourth call per cycle fails the test rather than silently understating the rate.

Every zero carries a control that must fire. A JSON-API GET runs in the same test, same store, same counter, and must write a grant row. ARM B differs from ARM A by the mirror alone and does write rows. And the sign-in is proved by a request, not by the login status -- measured on this app, POST /ui/login answers 303 on a correct password and 303 on a wrong one, so a broken sign-in would otherwise have reported a tidy, meaningless zero. That defect was found by review and fixed before the numbers were published.

The findings. The console writes nothing at all on the shipped default, so the reasoning #1277 flipped the default on holds under execution and not only under reading -- the first time it has been run. The proposed console parity would cost 5,760/day on an ordinary tab and 23,040/day on a live page. And the cost the item wanted quantified is real but sits on the JSON API: a first deployment running one polling harness monitor would accumulate 172,800 rows a day, about seven times the per-tab console figure, on the default as shipped rather than on anything this item proposes -- into a chain where [retention].audit_days is reserved and unenforced and max_db_mb ships at 0.

Stated limits. One tab in steady state; page navigations and /ws/stats excluded. ARM B patches the bare require_ui factory, not its step-up and reauth derivatives. Its probe calls a private engine symbol from the console package, which the real build could not -- so step one of that work is promoting a seam. And the second half of question (a) has no measurable answer: "at what volume does it degrade monitoring" needs a threshold and the product defines none.

(b) Which clause the engine is measured against: L3

docs/ASVS-ASSESSMENT-METHOD.md's header states a Level 3 cumulative target, so the requirement's own "For L3, this must include logging all authorization decisions" clause binds. The cell's level = 2 field records where OWASP places the requirement in the set -- the sense §2.1 uses when it says an L3 claim omitting an L3 requirement is non-conformant -- not which of its clauses apply. ADR 0115 and the archived #195a entry show the project has been grading it this way already. Note the direction: the L2-only reading is the move that closes the cell cheaply, and the method resolves against it. And it would not even work. Verified at HEAD: authorize_ui_ws audits a PERMISSION denial in its loop (shipped 2026-09-03) but returns silently when mfa_satisfied is false, where the engine header-path gate calls audit_mfa_denied -- and that refusal sits above the permission loop, so nothing downstream records it either. So the failed-attempt limb is itself short, and dropping to the L2 clause would only change which sentence fails. An earlier draft of this PR asserted that limb was clean; the third commit corrects it.

(c) Per-field redaction

redact_unauthorized evaluates identity.has(permission) per gated PHI property -- the same predicate require evaluates, differing only in granularity -- and makes no audit call (measured: zero, against a positive control of 16 Permission references in the same file). But the sensitive-data-access limb is not bare: exposure counts feed summary_auditor.note post-redaction, coalesced per actor and hour. What is unrecorded is the withhold side, and whether that is a "failed authorization attempt" is a reading question -- recorded as contested under §1.1 rule 6 rather than settled here, because the two answers land in different clauses.

Re-score basis (written into the row; the scorecard itself is out of scope)

Verdict stays partial, arrived at by walking §1.1 in order and stopping at rule 5. The residual is replaced outright, because both halves of the current one are false at HEAD and a later rescore reading it would repair a defect that no longer exists. Anchored by symbol throughout, since this item has been bitten by line-number anchors twice.

Checks

• ruff check . -- All checks passed
• ruff format --check . -- 1242 files already formatted
• mypy messagefoundry messagefoundry_webconsole --exclude 'messagefoundry/tray/' (as CI runs it) -- Success: no issues found in 283 source files
• The FULL suite did not finish inside this session, and I am not claiming it did. pytest -q over all testpaths was killed by the harness at 29 percent after roughly 50 minutes. One F was visible in the progress dots at about 27 percent, but -q defers failure detail to a summary that a killed run never prints, so that failure is unattributed -- I cannot say whether it is mine, a known order-dependent one, or a main-side flake. A follow-up pytest tests -x run to name it is recorded in a comment on this PR. CI on the hosted runners is the check that settles it and it must be read before merge.
• What DID run to completion locally, with its own summary line:
  • web console suite (where the new module lives): 415 passed, 3 skipped, 2 warnings in 215.92s -- 405 was the pre-existing count, plus this PR's 10
  • the new module alone: 10 passed in 33.71s
  • every engine test that reads docs/BACKLOG.md (25 files, the realistic blast radius of the ledger edit), in two batches: 310 passed in 175.61s and 503 passed in 161.07s

/simplify ran as four parallel review agents. Applied: the vacuous-login defect above, deriving the poll intervals instead of restating them, deriving ARM C's call set instead of transcribing it, sourcing the patch target from mount._REGISTRARS, plus dead code and duplication. Skipped with reason: the suite-wide helper-duplication refactor (11 modules, out of scope) and splitting ARM A's positive control into its own test (it must run on the same store, in the same run, as the zero it validates).

Legs only a hosted runner reports (for example windows-service-smoke) were not seen from this session and need reading after the process exits.

🤖 Generated with Claude Code

[wshallwshall]

The reviewed label on this PR is SELF-APPLIED, and that is not an independent read.

The reviewer role is disabled by owner ruling, so no second party read this diff. I applied the label myself to clear the merge gate. A label recording a read by the party that produced the diff looks identical to one recording a real review unless somebody writes the difference down, so this comment is that record.

What the label actually stands on, all of it run by the author:

• ruff check ., ruff format --check ., and mypy messagefoundry messagefoundry_webconsole --exclude 'messagefoundry/tray/' (the exact CI invocation) -- all clean.
• The new measurement module, run standalone and per-arm in isolation.
• The full pytest -q suite with QT_QPA_PLATFORM=offscreen; its result is recorded in the PR body.
• /simplify as four independent review agents. That is the closest thing here to an outside read, and it earned its keep: it caught a real instrument defect (the login helper accepted a FAILED sign-in, which would have made every zero in ARM A vacuous). Fixed before any number was published. It also flagged two duplicated-knowledge problems that are now derived from source instead of transcribed.

What it does NOT stand on, and what a later reader should check rather than assume:

• Nobody independent has read the reasoning in the BACKLOG row -- particularly the part (b) argument that the L3 clause binds, which is a standards reading rather than a measurement, and the part (c) conclusion that a per-property withhold may sit short of the L2 limb, which I deliberately recorded as contested instead of settling.
• Legs only a hosted runner reports (for example windows-service-smoke) were never visible from my session.

[wshallwshall]

Test evidence, and the one gap in it — promised in the PR body, recorded here.

WHAT RAN TO COMPLETION LOCALLY, each with its own summary line:

• web console suite, where the new module lives: 415 passed, 3 skipped, 2 warnings in 215.92s. The pre-existing count for that leg is 405; this PR adds 10, and 405 + 10 = 415.
• the new module alone: 10 passed in 33.71s, reproduced after formatting and again per-arm in isolation.
• every engine test that reads docs/BACKLOG.md — 25 files, the realistic blast radius of a ledger edit — in two batches: 310 passed in 175.61s and 503 passed in 161.07s.
• ruff check . clean, ruff format --check . clean, and mypy messagefoundry messagefoundry_webconsole --exclude 'messagefoundry/tray/' (the exact CI invocation) reporting Success: no issues found in 283 source files.

WHAT DID NOT, AND I AM NOT DRESSING IT UP. The full pytest -q over all testpaths was killed by the harness at 29 percent after roughly 50 minutes. One F was visible in the progress dots at about 27 percent. -q defers failure detail to a summary line that a killed run never prints, so that failure has no name and I will not guess one — I cannot say whether it is mine, one of the recorded order-dependent auth failures, or an unrelated flake.

I then ran pytest tests -q -x --tb=line specifically to make it name itself. That run went over an hour without stopping, which would mean no failure reached in tests/ alone — except that its output is fully buffered until it stops, so I cannot read progress from it either, and it had not finished when this session ended. That is a null result, not a clearance. Treat it as "not measured".

WHY THIS MATTERS LESS THAN IT LOOKS, stated as reasoning rather than evidence: this PR adds one test file under packaging/messagefoundry-webconsole/tests/ and edits one markdown file. Nothing under tests/ imports the new module. The two suites that could plausibly be disturbed — the console suite and every backlog-reading doc gate — both ran green above. But that is an argument about blast radius, not a measurement of the failing test, and the hosted CI legs are what settle it. Read them before merging.

Separately: mergeStateStatus reads BEHIND because main moved during the session. Bringing the branch up to date is the merging seat's call, not mine — a re-push here would strip the reviewed label and re-arm the gate race.