SQL inspection and logging: print or log the SQL Ferro renders and runs for a query or mutation #700

Problem Statement

A developer writes a query and wants to know what reaches the database:

adults = await User.where(lambda user: user.age >= 18).order_by(lambda user: user.name).all()

Ferro gives them no way to find out. No method returns the SQL a query renders, and no switch logs the statements a session executes. The choices are reading the Rust source, turning on Postgres statement logging, or guessing. A slow query, a wrong result, a test that should assert on the wire, or a reviewer who wants to see what an ORM change does to the SQL: each one is stuck.

Schema changes do not have this problem: ferro.migrate() returns a PassReport listing every DDL statement it ran, and ferro migrate new writes its SQL to step files. Queries and mutations have nothing equivalent.

The docs rewrite (#698) needs it too. Its rule is that every query example shows the SQL beside the call, captured from what Ferro runs rather than typed by hand (#725). The hand-written SQL in the Queries guide already differs from what Ferro sends.

Ferro's own logging works against the developer today: the ferro logger installs its own stream handler at import, at INFO, with propagation off, so nothing Ferro logs reaches the application's handlers, pytest's caplog, or a structured-logging backend.

Solution

Two doors onto the same statement, both rendered by the one function that sends it (ADR-0057):

The statement log. Every statement Ferro sends is one record on the ferro.sql logger at DEBUG, written as the statement finishes: the SQL with its placeholders, the parameters apart, secrets replaced by ***, the duration, and the operation it belongs to. Turning the logger on is the only switch.

logging.getLogger("ferro.sql").setLevel(logging.DEBUG)

async with engines.session():
    await User.where(lambda user: user.age >= 18).all()
# ferro.sql DEBUG SELECT "user"."id", "user"."name", "user"."age" FROM "user" WHERE "user"."age" >= $1 params=(18,) 0.4ms

The rendered statement. Every Query terminal carries a .sql() with the terminal's own signature that returns what the call would send, without sending it:

rendered = await User.where(lambda user: user.age >= 18).all.sql()
rendered.sql        # 'SELECT ... WHERE "user"."age" >= $1'
rendered.params     # (18,)
rendered.dialect    # 'postgres'
print(rendered)     # the SQL alone, ready for psql

await Account.where(lambda account: account.id == 1).update.sql(token=SecretStr("sk_live_2"))
# params: (***, 1)

The ferro logger stops installing a handler of its own and propagates, so both reach the application's logging configuration. The ferro migrate CLI, an application, installs its own handler so a data step's ctx.log lines still print.

User Stories

1. As a developer debugging a query, I want await query.all.sql() to return the exact SQL and parameters .all() would send, so that I can read what Ferro does without running it.
2. As a developer, I want .sql() on first, count, exists, update and delete too, each with that terminal's own signature, so that I can inspect any query-shaped call the same way.
3. As a developer, I want print(rendered) to give me the SQL alone, so that I can paste it into psql or sqlite3.
4. As a developer, I want rendered.params and rendered.dialect beside rendered.sql, so that I can see what each placeholder binds and which dialect's placeholders I'm reading.
5. As a developer, I want the rendered statement to be byte for byte what the call sends, placeholders included, so that there is never a second rendering to doubt.
6. As a developer, I want .sql() to resolve its database the way the call would (the enclosing session, using=, session=), so that a Postgres query renders with Postgres's casts and a SQLite one with SQLite's.
7. As a developer, I want .sql() outside a session to raise the same "no database route" error the call would, so that I learn the rule once.
8. As a developer, I want .sql() on update and delete to send nothing and change nothing, so that inspecting a mutation is always safe.
9. As an application developer, I want every statement Ferro sends logged on ferro.sql at DEBUG, so that I can see what my app does to the database by setting one logger's level.
10. As an application developer, I want queries, mutations, raw SQL, transaction control (BEGIN, COMMIT, ROLLBACK, savepoints), session-settings statements, the catalog probe and migration DDL all in the log, so that the log is the whole truth of what ran, not a selection.
11. As an application developer, I want each record to carry the SQL, the parameters, the dialect, the duration, the operation (fetch, save, bulk_create, update, delete, raw, transaction, settings, catalog, migrate), the configured connection name and the affected row count where the driver reports it, as structured attributes, so that structlog, Logfire or JSON handlers get fields rather than a string to parse.
12. As an application developer, I want the message line to read as SQL, then parameters, then duration, so that a plain StreamHandler is useful too.
13. As an application developer, I want a failed statement to leave a record carrying the error, so that the log shows what was attempted when an exception propagates.
14. As an application developer, I want a multi-statement operation (a chunked bulk_create, a many-to-many add) to log one record per statement in the order sent, each with the same operation name, so that I can follow it without a grouping record.
15. As an application developer, I want the log to cost nothing when ferro.sql is not enabled for DEBUG, so that leaving it configured in production is free.
16. As an application developer, I want a value that is a SecretStr or SecretBytes to appear as *** in every record and in every rendered statement, so that a secret never lands in a log file.
17. As an application developer, I want a plain value bound to a column whose field is declared SecretStr or SecretBytes (where(lambda account: account.token == "hunter2")) to appear as *** too, so that the column's declaration protects it even when the literal is not a secret type.
18. As a developer writing tests, I want the *** marker to be a sentinel I can distinguish from the string '***', so that a test can assert a parameter was redacted.
19. As an application developer, I want Ferro's loggers to propagate to my handlers and never install a handler of their own, so that Ferro's logging obeys my logging configuration like every other library's.
20. As a developer running pytest, I want caplog to capture ferro.sql and ferro records, so that a test can assert on the SQL a call emits.
21. As a ferro migrate user, I want the CLI to keep printing a data step's ctx.log lines, so that the logger change does not silence my migrations.
22. As a developer calling the migration API from Python, I want the docs to tell me that data-step info lines appear once I configure logging, so that I am not surprised by a quiet run.
23. As a developer who read the ferro logger's ferro migrate: <ddl> debug lines, I want those statements to appear as ferro.sql records instead, so that there is one log of statements, not two.
24. As an auto-migrate user, I want PassReport unchanged, so that code reading report.statements keeps working.
25. As a docs reader, I want a guide page that shows turning the log on, a captured record, and .sql() on a query and on an update, with the Account model in both field-declaration styles, so that I can see the feature before I use it.
26. As a docs reader, I want the .sql() docstring to carry a runnable example against the reference prelude, so that the API reference shows the call and its output.
27. As a docs author (Show captured SQL beside query and mutation examples (needs #700) #725), I want to capture the statement log through an ordinary logging handler in the docs harness, so that every query example can show the SQL Ferro sent without a capture API.
28. As a Ferro maintainer, I want a pin that, for every terminal on both dialects, asserts .sql() equals the record the executed call wrote, so that the two doors cannot drift.
29. As a Ferro maintainer, I want the decision "this bind is secret" made once in Python and carried to Rust beside the binds, so that no second rule can disagree with the first.

Implementation Decisions

The one renderer. Each Query terminal's statement is built by the same Rust function whether it is sent or rendered. Rendering runs that function up to, and not including, the send: it reads the plan from the QueryIR payload, resolves the route, reads the cached catalog where the dialect needs it, and returns the SQL and the bound values instead of executing. There is no Python-side or model-only renderer (I-1's phantom-diff rule applied to queries).

Rendering resolves a database. .sql() is async and routes like the terminal it mirrors (enclosing session, using=, session=). On Postgres the statement's casts follow the live table (the catalog probe, cached per table per schema epoch); on SQLite no probe runs. Outside a session it raises the existing no-route error. It opens no transaction, writes nothing to the identity map, and sends nothing but the cached probe.

Terminals carry .sql() through a decorator. all, first, count, exists, update and delete stay async def methods; a decorator gives each a .sql attribute with the same signature as the method. The decorator, not a descriptor, so the API reference still renders each as a method. The bound .sql is typed as a callable with the terminal's parameters, carried through the Relation and ProjectedQuery overrides of all, first and count. update.sql accepts both of update()'s forms.

RenderedSql. A frozen dataclass with sql: str, params: tuple, dialect: str ("postgres" / "sqlite"); __str__ returns sql. Exported from ferro.

The statement log is a logger, and the only switch. Records go to logging.getLogger("ferro.sql") at DEBUG. There is no echo= flag, connection option or setting. Python checks isEnabledFor(DEBUG) once per operation, where the operation is dispatched over FFI (it already holds the GIL there), and passes the answer with the route. When off, Rust collects nothing. When on, Rust emits each statement's data to one Python callable as the statement finishes, taking the GIL once per statement; that callable builds the message line and the LogRecord with its extra fields. Rust formats nothing.

Every statement, one record each. The record is emitted from the engine's execute/fetch layer, the single place every statement passes through: operations, raw SQL, the catalog probe, transaction control, session-settings delivery, and DDL from the reconciliation pass and migration runs. One record per statement, after it finishes, carrying duration_ms; a statement that fails emits a record with error set before the exception propagates. Multi-statement operations emit one record per statement under the same operation; nothing groups them. The free-text ferro migrate: <ddl> debug lines on the ferro logger are removed in favour of these records; PassReport is unchanged.

Record attributes. sql, params (a tuple; secrets as the sentinel), dialect, duration_ms (float), operation, connection (the configured name), rows (int or None), error (None or the message). The message line is <sql> params=<params> <duration>ms; with error, the duration is followed by failed: <error>.

Redaction, decided once in Python. A bound value is replaced by the REDACTED sentinel (a singleton whose repr is ***) when it is a SecretStr/SecretBytes, or when it is bound to a column whose field is declared one. The mask is computed in Python where the model's secret fields (recorded by #760) and the value types are known, and travels to Rust as a per-bind flag beside the binds; Rust applies the flag when it emits and never re-derives it. .sql()'s params are redacted by the same mask. Session settings are delivered as statement text (Postgres SET takes no bind parameters), appear inline and are not redacted. Raw SQL is redacted by value type only, since no column is known.

The ferro logger. At import, ferro attaches a NullHandler and leaves propagation on; the stream handler, level and propagate = False are gone. The ferro migrate CLI installs its own stream handler on ferro at the level it uses today, so data-step ctx.log lines print as before. The migration guide notes that a programmatic caller sees those lines once it configures logging.

The parity pin. A test over every terminal, on both dialects, with a model carrying a secret column: await query.<terminal>.sql() equals the ferro.sql record of the executed call in sql, params and dialect. It is the query-side counterpart of I-1's cross-emitter pins and is listed under I-1's enforcement in AGENTS.md.

Docs. One guide page under the Queries area, "Inspecting SQL", with the Account model in both field-declaration styles (I-7), lambda predicates named after the model (I-8), every block runnable; docstrings for .sql(), RenderedSql and the ferro.sql logger in reference form (I-14), the .sql() example against the reference prelude. The glossary terms are Statement log and Rendered statement (GLOSSARY.md).

Testing Decisions

A good test drives the public API and reads the two public outputs, the ferro.sql records and the RenderedSql value; it never reaches into how Rust carries the mask or where the GIL is taken.

• Seam A, the ferro.sql logger from Python, on both dialects. A shared fixture attaches a collecting handler to ferro.sql at DEBUG (generalising the ferro_log fixture the DDL lock-timeout tests use for the ferro logger). Tests run under backend_matrix and assert on records for: a where/order_by/include fetch, count and exists, save (insert and update), bulk_create across a chunk boundary, update() and delete(), a many-to-many add, raw.execute/fetch_all, a transaction() block with a savepoint, a session with settings, the catalog probe on Postgres, ferro.migrate() DDL, and a statement that fails. Each asserts the attributes it is about; the secret cases assert the REDACTED sentinel by identity and that the real value appears in no record's message. The "off costs nothing" story is asserted by driving an operation with the logger disabled and checking no handler call and no record.
• The parity pin at the same seam, for every terminal and dialect.
• The logger change through pytest's caplog: a ferro.sql record and a ferro record are both captured, and logging.getLogger("ferro") has only a NullHandler after import. The CLI's handler is asserted through the existing CLI tests' output.
• Seam B, the docs harness. The guide page's blocks and the .sql() docstring example run under the existing docs tests.
• Prior art: the ferro_log fixture in the DDL lock-timeout tests; tests/test_cross_emitter_parity.py for the pin shape; the backend_matrix / postgres_only markers; tests/test_docstring_examples.py and tests/test_docs_examples.py for Seam B.
• No new Rust unit tests: Rust emits data and formats nothing; cargo test keeps compiling.

Out of Scope

• An ad hoc capture context manager (capture_sql()): dropped; a handler on ferro.sql captures the same records.
• .sql() on instance save/delete, bulk_create and the many-to-many operations: seen through the log now; the same decorator extends to them in a follow-up.
• Redacting SET LOCAL values or anything inside raw SQL text.
• The per-example SQL in the docs (Show captured SQL beside query and mutation examples (needs #700) #725) and the docs harness handler it needs: Show captured SQL beside query and mutation examples (needs #700) #725's ticket, built on this.
• Encrypting stored secrets (Encrypted fields: encrypt on write and decrypt on read with a developer-supplied cipher #761).
• Grouping records per operation, sampling, slow-query thresholds, or a metrics hook.
• Timings finer than the client-side duration (no server-side EXPLAIN).

Further Notes

• Builds on SecretStr and SecretBytes fields save as '**********' and hydrate as plain str #760 (merged in PR fix: SecretStr and SecretBytes fields store the real value and hydrate as secrets (#760) #762): redaction by column reads the secret fields it records, and the stored value is right before the log of it is.
• The ferro logger change is a behaviour change for anyone who relied on Ferro's stream handler printing to stderr; the release notes say so and show the two-line logging setup that restores it.
• Design record: ADR-0057; grill transcript in the session that produced it. Industry reference points: Prisma's $on('query') event (query, params, duration), Django's django.db.backends DEBUG log, Rails filter_attributes → [FILTERED], Kysely compile() / Drizzle toSQL() for the {sql, params} shape.