[0x054]

Summary

Epic: #700 (SQL inspection and logging). Three of its four slices; the guide page (#767) follows once the docs rewrite (#698) lands, so this PR does not close the epic.

A developer can now see what Ferro sends, two ways, both from the one function that builds and sends each statement:

query.all()                    ┐
query.all.sql()                ├─► build_<terminal>(plan, dialect, cached catalog) ─► sql + binds
                               ┘        │                                  │
                                        │ send (Executor → EngineHandle)   │ RenderedSql(sql, params, dialect)
                                        ▼                                  │   str() is the SQL alone
                        sql_log::observe at the engine chokepoint          │   params masked like the log
                                        ▼                                  │
                  logging.getLogger("ferro.sql") DEBUG, one record per     │
                  statement as it finishes: sql, params (secrets as ***),  │
                  dialect, duration_ms, operation, subject, connection,    │
                  rows, error ◄────────── parity pin ──────────────────────┘

• Statement log (Statement log: the ferro.sql logger and the Rust emit path, proven on migration DDL #764, Statement log: every operation statement, with secrets redacted #765): every statement Ferro sends (queries, mutations, bulk and many-to-many, raw SQL, BEGIN/COMMIT/savepoints, the session-settings batch, the catalog probe, migration DDL) is one ferro.sql record. The logger is the only switch: Rust asks once per FFI entry whether it is enabled, opens a task-local context only then, and hands each record's data to one Python callable that formats it. Off costs nothing. The ferro logger now installs a NullHandler and propagates; the ferro migrate CLI installs its own handler.
• Redaction (Statement log: every operation statement, with secrets redacted #765): a bound value equal to a secret-typed literal or field value Python unwrapped, or bound to a column declared SecretStr/SecretBytes, is emitted as *** (a sentinel, REDACTED, so tests can tell it from the string).
• Rendered statement (Rendered statement: .sql() on every Query terminal, and the parity pin #766): every Query terminal (all, first, count, exists, update, delete) carries .sql() with the terminal's own signature, returning RenderedSql; rendering routes like the call, reads only the cached catalog, opens no transaction and writes nothing. tests/test_rendered_statement.py pins .sql() equal to the executed call's record for every terminal on both dialects (listed under I-1's enforcement in AGENTS.md).

Design: ADR-0057; glossary terms Statement log and Rendered statement. Accepted deviations are on #700's plan comment: redaction as a secret-value set rather than a positional flag; scope's PyResult bound; count_filtered(operation=); close_session(connection_name); render_count standing in for render_exists.

Architecture

The design rests on one rule: a statement is built in one place, and both doors read from it. Everything else follows from keeping that rule cheap.

One build function per terminal. Each Query terminal used to build and send its statement in one body. The build step is now its own function (build_fetch, build_count, build_update, build_delete in the Rust core), and two entry points call it: the executing one sends the result, the rendering one returns it. There is no second renderer, so await query.all.sql() cannot drift from what await query.all() sends, and a test pins the two equal for every terminal on both dialects. This is I-1 applied to queries: the same reason the migration doors share one planner.

The engine chokepoint, not the call sites. Every statement Ferro sends passes through a handful of execute and fetch methods on the engine connection. Those methods take the time and emit the record after the statement finishes, so one place covers queries, mutations, raw SQL, transaction control, session settings, the catalog probe and migration DDL. A statement that fails emits a record with its error before the exception propagates. The fix round closes the gap the panel found: the Postgres run-lock statements used the raw driver and bypassed this layer.

The switch is the logger, checked once per operation. Each FFI entry already holds the GIL when Python calls it, so it asks logging.getLogger("ferro.sql").isEnabledFor(DEBUG) once and opens a tokio task-local statement context only when the answer is yes. The chokepoint reads that context; outside one it does nothing. Off costs nothing. On, the GIL is taken once per statement to hand the record's data to one Python callable, ferro._sql_log.emit, which builds the message and the LogRecord. Rust formats nothing, so the record's shape lives in one Python function. There is no echo= flag or setting to disagree with the logger.

Redaction is a set of values, matched when the record is written. Rust builds the binds from the query plan, so Python never sees them one at a time, and a positional mask was not available. Instead each operation carries a secret-value set: Python adds every value it unwrapped from a SecretStr or SecretBytes (predicate literals, field values on save and update, raw arguments), and Rust adds every value bound to a column the model declares secret, for the root model and every joined one. A bind equal to a value in the set is emitted as the REDACTED sentinel. Matching by value over-masks in one case, a plain value that happens to equal a secret, and never under-masks. The rendered statement's params go through the same set, so .sql() and the log show the same ***. (The panel's F1 and F2 are this design's two gaps: keyset cursors were not added to the set, and the set was a list; the fix round adds them and hashes it.)

Terminals carry .sql() through a decorator. all, first, count, exists, update and delete stay async def methods; a decorator makes each a callable with a .sql attribute of the same signature. A decorator rather than a class-level descriptor so the API reference still renders each as a method, and a typed descriptor for update so its two forms stay distinct to ty. The same decorator can extend .sql() to save, bulk_create and the many-to-many operations later without a new API.

The library stops owning a handler. ferro installs a NullHandler and propagates, the standard posture for a library, so the records reach whatever the application configured: caplog, structlog, a JSON handler. The ferro migrate CLI is an application and installs its own stream handler, so a data step's ctx.log lines print as before.

The decisions and their rejected alternatives (an offline renderer from the model, an echo= flag, a string-kind query.sql("update"), a capture_sql() context manager) are recorded in ADR-0057; the glossary names the two artifacts Statement log and Rendered statement.

Evidence

• Before: no API returns a query's SQL; ferro's own StreamHandler with propagate=False kept its debug lines out of caplog and application handlers.
  After: on bcb9931, full suite on SQLite and Postgres: 4875 passed, 77 skipped, 2 xfailed; cargo test --no-default-features --features testing 382 passed; ty and ruff clean. Each slice's Verify block ran green on its PR head (fresh reviewer) and again on the integration branch after merge.

Merge Danger

Door: two-way for the code; one-way for the logging behaviour users observe.

Reverting the branch restores the old logger setup. The behaviour change itself: anyone who relied on Ferro's own stderr handler printing ferro INFO lines (data-step ctx.log output when calling the migration API from Python) now sees them only once they configure logging, which the Connections guide's new Logging section says. Release notes should carry that line.

Blast Radius: medium

Every FFI operation entry is now wrapped in the statement-log scope (bodies unchanged, verified by review); count_filtered and close_session gained parameters (internal _core API, callers updated); Query.update is now a typed descriptor with the same two overloaded forms (pinned by ty fixtures). No wire-format change: golden vectors are byte-identical.

🤖 Generated with Claude Code

https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP

[0x054]

Verdict: FIX FIRST

One Critical (a plain keyset cursor on a secret order column reaches the log and .sql() unredacted, reproduced on both dialects) and a Spec FAIL (the run-lock statements never reach the log).

Spec: FAIL

• Important · src/run.rs:714, src/run.rs:823, src/run.rs:851 at bcb9931 · Missing · Three run-lock statements go straight to sqlx on a detached pool connection and skip the engine's execute/fetch layer: SELECT pg_try_advisory_lock($1), the held-by-this-session probe, and SELECT pg_advisory_unlock($1). A ferro migrate up on Postgres sends all three inside the logged(...) scope that LockScope.__aenter__/__aexit__ open (src/migrations_ffi.rs), yet none of them leaves a ferro.sql record. The governed_schema read beside them does get one, so the log of a run has holes. · The epic says the statement log is "the whole truth of what ran, not a selection" (story 10). Implementation Decisions say the record comes from "the engine's execute/fetch layer, the single place every statement passes through", including "DDL from the reconciliation pass and migration runs".
• Minor · src/backend.rs:80, src/backend.rs:148 at bcb9931 · Missing · Two statements Ferro sends from pool hooks are never logged: the after_connect hook's SET search_path TO … and the after_release guard's SELECT coalesce(current_setting($1, true), ''). · Epic story 10 and the definition "every statement Ferro sends is one record".
• Minor · src/operations.rs:4697, 4790, 4872 and src/ferro/query/builder.py:1326 at bcb9931 · Misunderstood · Records use operation names outside the epic's list: count, exists, m2m_add, m2m_remove, m2m_clear. The epic names exactly fetch, save, bulk_create, update, delete, raw, transaction, settings, catalog, migrate. No shipped doc lists the extra names; the Connections guide table documents only "migrate". · Epic story 11 and "Record attributes".
• Minor · src/ferro/_sql_log.py:65 at bcb9931 · Extra · Records carry a subject attribute that the epic's attribute list does not include. Ticket Statement log: the ferro.sql logger and the Rust emit path, proven on migration DDL #764 asked for it, so it is ticket-sanctioned but goes beyond the epic. · The epic's "Record attributes" list is sql, params, dialect, duration_ms, operation, connection, rows, error.

Deferred to #767/#725, not counted as Missing: the Inspecting SQL guide page; the migration-guide note on data-step info lines (story 22); an API-reference entry for the ferro.sql logger; per-example SQL and the docs-harness handler.

Cannot verify: .sql() on a connection-delivery Postgres session that has not pinned yet (OperationScope::unwrapped calls hold_pinned_connection, src/session_settings.rs:1241, which may send the settings batch on first pin and break "sends nothing but the cached probe"; unchanged code). .sql() inside a transaction-delivery session that sets search_path through settings: rendering probes the catalog on the pool route outside the SET LOCAL scope, so its casts could differ from the call's (unchanged code).

Coherence

• Minor · src/operations.rs:3412 at bcb9931 · build_fetch returns BuiltFetch { statement, schema, join_plan, include_hops }, not the BuiltStatement that Rendered statement: .sql() on every Query terminal, and the parity pin #766's Interfaces line names. Both twins still read .statement from the one builder, so the contract holds.

Every other shared interface agrees, producer against consumer: enabled; scope (the Deviated PyResult form, every caller passes a PyResult future); StatementContext; observe (called from every EngineConnection execute and fetch method and from BEGIN); with_subject; with_operation (added, used for settings and the catalog probe); emit/REDACTED (both consumers take shown_params' (params, mask)); the secret_values keyword on all ten ticketed FFI entries and the four render_* twins; CompiledQuery.secret_values; secret_values_of/secret_values; secret_columns_for; count_filtered(operation=) matched by render_count(operation=); close_session(session_id, connection_name); each executing entry and its render entry call the same build_fetch/build_count/build_update/build_delete; RenderedSql; terminal → TerminalMethod[S, P, R], update through _update_terminal; the statement_records fixture.

Findings

Critical

• F1 security · src/operations.rs:1590-1612 @ bcb9931 · conf 95 · Plain keyset position on a secret column is logged and rendered unredacted
  plan_secret_values collects literals bound to secret columns from plan.where_clause and plan.set_assignments only; it never reads plan.after / plan.before, and wire.py:994-996 (_secret_literals) collects position values only when they are SecretStr/SecretBytes instances. Input: Account.select().order_by(lambda account: account.token).order_by(lambda account: account.id).after(("sk_live_CURSOR", 0)) with token: SecretStr and a plain-str cursor (as decoded from an API page token). Effect: the record's message and params show ('sk_live_CURSOR', 'sk_live_CURSOR', 0), and so do RenderedSql.params and str(rendered) from .all.sql(); before(...) takes the same path. · ADR-0057 and epic story 17 say a value bound to a declared secret column is ***; the keyset filter binds the position against the secret order column twice (> and =), so a secret reaches the log file and any bug report that prints the rendered statement. · Fix: in plan_secret_values, pair each after/before value with its order_by term (resolving traversed order keys through the joins as collect_secret_leaf_binds does) and add it through literal_secret_binds when that column is secret; add a statement-log test and a parity-pin case paging with after/before on a secret order key with a plain str. · verified by: read plan_secret_values (loops only where_clause and set_assignments); QueryPlan.after/before at query.rs:504,507; throwaway probes on SQLite (params=('sk_live_CURSOR', 'sk_live_CURSOR', 0)) and Postgres (RenderedSql.params == ('sk_live_CURSOR', 'sk_live_CURSOR', 0)). [ADR-0057] [epic story 17]

Important

• F2 adversarial · src/sql_log.rs:277-279 @ bcb9931 · conf 92 · Redaction is O(binds × secrets) under the GIL; bulk_create with the log on goes quadratic
  mask_of runs a linear secrets.contains(bind) over a Vec for every bind of every statement; for bulk_create, save_bulk_records (src/operations.rs:3124-3126) builds the secret set from every row's secret value twice (Python's _secrets_to_mask and Rust's payload_secret_values over the same rows), nothing deduplicated or hashed, so every chunk statement scans all binds against 2N secrets inside Python::attach. · Measured on SQLite with a NullHandler: 5k rows 0.65 s on vs 0.03 s off; 20k 9.99 s vs 0.13 s; 40k 64.8 s vs 0.24 s; a 100k-row import with debug logging on hangs the process for minutes, and ADR-0057 promises one GIL take per statement to write the record. · Fix: a HashSet (or sorted, deduped set) so each bind is one lookup; stop adding the Python- and Rust-collected payload values twice; compute the mask outside Python::attach. · verified by: read mask_of, operation_secret_values, payload_secret_values, save_bulk_records; ran the scratchpad bulkprobe.py at n = 5000, 20000, 40000. [ADR-0057]
• F3 correctness+spec · src/run.rs:714 (also :823, :851) @ bcb9931 · conf 82 · Run-lock statements bypass the statement log
  pg_try_advisory_lock, the HELD_BY_THIS_SESSION probe and pg_advisory_unlock are sent with raw sqlx::query on a detached connection and never call sql_log::observe, though the run's migrate scope is open around them. · With ferro.sql at DEBUG, a Postgres migration run logs its DDL but not the lock it took, probed and released; a reader debugging a lock wait, or a test asserting the log is complete, sees a silently incomplete record (story 10). · Fix: send the lock statements through EngineConnection or a shared observed helper so they emit under the run's scope. · verified by: grep of sqlx::query/.execute(&/.fetch_one(& call sites in src/*.rs; read run.rs 700-860; grep of tests/test_statement_log.py for advisory found nothing. [epic story 10] [epic Implementation Decisions: every statement, one record each]
• F4 testing+depth · tests/test_statement_log.py:848 @ bcb9931 · conf 82 · Log-off test spies private helpers and misses the query-side collectors
  test_with_the_log_off_no_operation_emits_or_collects_secrets monkeypatches ferro.models.secret_values and ferro.raw.secret_values_of and asserts they were never called; the query paths build secret sets through compile_query / _secret_literals / wire.secret_values_of (src/ferro/query/wire.py:992,1113), which is never spied, and Query.update/Query.delete are not exercised with the log off. · Ticket Statement log: every operation statement, with secrets redacted #765 requires "no secret-value set is built (asserted with a spy and a counter on the collecting helpers)"; the test stays green if compile_query or the update path collects unconditionally, so the zero-cost claim is unpinned for fetch, count, update and delete, while a rename or inlining of either patched helper breaks it with AttributeError although behaviour is unchanged. · Fix: assert the property at one public seam (no emit call, plus one collect-secrets entry the operations call, spied once), cover wire.py's collector, and add update/delete to the log-off body. · verified by: read the test body (848-893); grep of secret_values usage in models.py, raw.py, builder.py, wire.py.

Minor

• F5 standards-and-invariants+spec · src/ferro/models.py:61-69 (and src/ferro/raw.py:71-78) @ bcb9931 · conf 80 · The log switch is read twice per operation, in two near-identical helpers
  save()/bulk_create() and raw execute/fetch_all/fetch_one each gate secret collection on _SQL_LOG.isEnabledFor(DEBUG); each FFI entry then reads the logger again in Rust (sql_log::enabled inside operation_log). A level raised between the two reads sends an empty secret set while Rust logs, so a SecretStr bound through raw SQL (no column known) is written unredacted; and the two _secrets_to_mask copies must change together. · ADR-0057: "checks isEnabledFor(DEBUG) once per operation … One switch cannot disagree with another." · Fix: read the switch once per operation (always pass the cheap Python-collected values, as the render path already does through compiled.secret_values, or have Rust call the collector only when its own check is true), in one helper in _bind_payload.py or _sql_log.py. · verified by: ADR-0057 quoted; grep on the head shows the gates at models.py:67 and raw.py:77; operation_log calls sql_log::enabled(py) independently. [ADR-0057]
• F6 depth · src/ferro/query/rendered.py:95 @ bcb9931 · conf 80 · The (params, mask) → REDACTED substitution is held by two Python consumers
  The engine returns params with None in secret positions plus a parallel mask; _sql_log.emit and rendered.send each zip(..., strict=True) and substitute REDACTED. · A third consumer, or a change to the stand-in, must remember the pairing; the two copies can drift and the rendered statement then disagrees with the log record. · Fix (follow-up): one _sql_log function turns the engine's pair into the shown tuple for both, or the engine returns REDACTED-ready params. · verified by: read emit and send in full and shown_params in sql_log.rs.
• F7 maintainability · src/operations.rs:4571-4574 @ bcb9931 · conf 82 · Same secret-value assembly pasted in eight query entries
  operation_secret_values(&secret_values, plan_secret_values(py, &model_class_for(py, &name)?, &plan)?) is written out in count_filtered, update_filtered, delete_filtered, render_count, render_update, render_delete; the save and fetch entries differ only in their source. · Duplicated Code: a new terminal or a new source of secret binds means eight edits, and a missed one leaks a secret for one terminal only (F1 is that shape). · Fix: one query_secret_values(py, &name, &plan, &secret_values) used by both twins. · verified by: read the four entries; six verbatim plan_secret_values(py, &model_class_for additions in the diff.
• F8 api-contract+standards-and-invariants · docs/pages/guide/connections.md:243 @ bcb9931 · conf 80 · operation documented as only "migrate" while the PR emits eleven more values
  The attribute table says operation is ""migrate" for the reconciliation pass and ferro migrate"; the PR also emits fetch, count, exists, save, bulk_create, update, delete, raw, transaction, settings, catalog (src/sql_log.rs consts; src/operations.rs:1422). · The record attribute names and values are the contract for structlog/JSON handlers; a filter written against the table is wrong today and a later rename breaks it silently. · Fix: list every value in the same PR that emits them (or link Docs: the Inspecting SQL guide page #767's page once it exists). · verified by: read connections.md:221-251; grep of pub const in sql_log.rs and StatementContext::new call sites.
• F9 spec+correctness · src/backend.rs:80 (and :148) @ bcb9931 · conf 82 · Pool-hook statements are never logged
  The after_connect hook's SET search_path TO … and the after_release guard's SELECT coalesce(current_setting($1, true), '') run with raw sqlx::query outside any scope. · Story 10 says every statement Ferro sends is one record; these run outside an operation, so either log them under a pool operation or state the exclusion in the spec and docs. · verified by: read backend.rs 70-90 and 140-150; no observe call, no scope.
• F10 spec · src/ferro/_sql_log.py:65 @ bcb9931 · conf 80 · Records carry subject, which the epic's attribute list does not include
  Ticket Statement log: the ferro.sql logger and the Rust emit path, proven on migration DDL #764 asked for it (the pass's table or enum type; a run's NNNN_name/<step file>), so it is ticket-sanctioned; the epic and the Connections table should name it. · verified by: epic "Record attributes" list vs _sql_log.emit.
• F11 review-pr · docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md:36 @ bcb9931 · conf 85 · ADR-0057 still describes the positional per-bind mask the code does not ship
  The ADR says the mask "is decided in Python … travels to Rust beside the binds; Rust never re-derives it"; the shipped rule is a set of secret values matched by equality at emit, with Rust adding the values bound to secret columns (plan_secret_values, payload_secret_values), accepted on the plan's Deviated line but recorded nowhere an agent searches first (I-5). · Fix: amend ADR-0057's redaction section (or add a superseding note) to the value-set rule, including that a plain parameter equal to a secret is masked. · verified by: ADR text vs operations.rs:1590, 1616.
• F12 coherence · src/operations.rs:3412 @ bcb9931 · conf 80 · build_fetch returns BuiltFetch, not the ticketed BuiltStatement
  Both twins read .statement from the one builder, so the contract holds; the ticket's Produces line and the plan should say BuiltFetch. · verified by: read build_fetch and both callers.

Invariants and ADRs

Checked: AGENTS.md (I-1 enforcement list and the new pin entry, I-2, I-3, I-6, I-8, I-10, I-13, I-14), GLOSSARY.md (Statement log, Rendered statement, Compiled query, QueryIR payload, Session settings, Operation atomicity, Materialization plan), docs/adr/0057 in full, ADR-0049 (PassReport unchanged, judged from the diff), epic Implementation Decisions and Out of Scope, the plan's Deviated line, tickets #764–#767 Interfaces; added Rust lines grepped for unwrap()/expect/panic! (only under #[cfg(test)]); CHANGELOG.md untouched; git log -S on the removed propagate=False (df6be66, added only to avoid duplicate lines; its one in-repo consumer rewritten in this PR).
Violations: F1 [ADR-0057] [epic story 17]; F2 [ADR-0057, one GIL take per statement]; F3, F9 [epic story 10]; F5 [ADR-0057, one switch]; F11 [I-5, decision record contradicts the code].
Candidate ADRs: (1) an emitter or handler error on ferro.sql fails the operation after its statement ran, so an autocommit write that committed reports failure (I-6 as applied; scope's PyResult bound); (2) a statement dropped by asyncio cancellation mid-send leaves no record; (3) over-redaction by value equality is accepted and never leaks (the plan's Deviated line, not yet in an ADR; see F11).
Terminology drift: none.

Coverage

Personas: correctness, testing, maintainability, standards-and-invariants, history, depth, security (secrets reach the log; redaction rule), adversarial (≥300 executable lines; data-mutation paths wrapped), api-contract (exported types and _core signatures changed). reliability dropped by the 9-persona cap; data-migration not applicable.
Dropped below confidence 80: 0. Cannot verify from diff: .sql() on a connection-delivery session before it pins (settings batch on first pin?); the catalog probe on the pool route outside a SET LOCAL search_path scope; Postgres errors whose primary message echoes a bound value (invalid input syntax for type …: "<value>") would land a secret in error (unique violations on both dialects were probed and carry no value); a blocking ferro.sql handler runs under the GIL on a tokio worker while a transaction's connection guard is held; whether any of the full suite's 7 warnings is new; inspect.iscoroutinefunction(Query.all) is now False (terminal descriptor), no in-repo consumer found.
Verify: passed on bcb9931 (#764/#765/#766 Verify blocks on sqlite+postgres; cargo test --no-default-features --features testing 382 passed; ty, ruff clean; full suite pytest tests --db-backends=sqlite,postgres 4875 passed, 77 skipped, 2 xfailed). Trial merge: not run (base unchanged).

Residual risk

• The ferro logger posture change (NullHandler + propagate) silences INFO lines users may have relied on and can duplicate lines where root is configured; needs an upgrade note in the release.
• observe runs user logging handlers synchronously on tokio worker threads under the GIL, mid-statement, with a transaction's connection guard held; a slow handler stalls that connection's queue.
• Redaction over-masks by value equality (a non-secret bind equal to a secret shows ***); never leaks, but can mislead someone debugging; one sentence in the docs page.
• Secrets can still reach error text if a Postgres error echoes the input value; worth a probe of the raw-SQL path with a typed column.