From 2d1cf159cb8a261c56f2c28e3f272090df310c07 Mon Sep 17 00:00:00 2001 From: 0x54 Date: Wed, 21 Oct 2026 02:01:03 -0400 Subject: [PATCH 1/5] feat(log): statement log records on ferro.sql for migration DDL (#764) (#768) The statement log exists: every statement the reconciliation pass or a migration run sends is one ferro.sql DEBUG record with sql, params, dialect, duration_ms, operation, subject, connection, rows and error. Rust asks Python once per FFI entry whether the logger is on, opens a task-local statement context only then, and hands each record to ferro._sql_log.emit; the ferro logger installs a NullHandler and propagates, and the CLI installs its own handler. Interfaces changed: scope(ctx, fut) -> PyResult where F: Future> (the ticket had no output bound; an emitter error must come back as the operation's result). Closes #764 Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP --- docs/pages/guide/connections.md | 34 +++ docs/pages/guide/schema/auto-migrate.md | 2 +- src/backend.rs | 150 +++++++--- src/connection.rs | 21 +- src/ddl_exec.rs | 44 ++- src/ferro/__init__.py | 14 +- src/ferro/_sql_log.py | 70 +++++ src/ferro/cli/__init__.py | 31 ++- src/lib.rs | 1 + src/migrate.rs | 11 +- src/migrations_ffi.rs | 101 +++++-- src/run.rs | 6 - src/schema.rs | 20 +- src/sql_log.rs | 336 +++++++++++++++++++++++ tests/conftest.py | 29 ++ tests/test_ddl_lock_timeout.py | 51 ++-- tests/test_statement_log.py | 351 ++++++++++++++++++++++++ 17 files changed, 1105 insertions(+), 167 deletions(-) create mode 100644 src/ferro/_sql_log.py create mode 100644 src/sql_log.rs create mode 100644 tests/test_statement_log.py diff --git a/docs/pages/guide/connections.md b/docs/pages/guide/connections.md index b8aa8bbe..0f3fcf2d 100644 --- a/docs/pages/guide/connections.md +++ b/docs/pages/guide/connections.md @@ -216,6 +216,40 @@ See [Testing](../howto/testing.md) for a ready-made pytest fixture. !!! note "No `disconnect()` yet" An explicit `disconnect()` is **not yet implemented** — pools are cleaned up on process exit. See the [Roadmap](../roadmap.md). +## Logging + +The `ferro.sql` logger is the statement log: one `DEBUG` record for each statement Ferro sends, written as the statement finishes. Turn it on with your usual logging setup: + +```python +import logging + +logging.basicConfig(format="%(name)s %(levelname)s %(message)s") +logging.getLogger("ferro.sql").setLevel(logging.DEBUG) +``` + +A schema change now prints each statement it runs, with its parameters and how long it took: + +```text +ferro.sql DEBUG CREATE TABLE IF NOT EXISTS "post" (...) params=() 1.2ms +ferro.sql DEBUG ALTER TABLE "author" ADD COLUMN "bio" varchar params=() 0.8ms +``` + +A statement the database rejects ends its line with `failed: `, and the error still raises. Each record also carries the statement as attributes, so a structured handler reads fields instead of parsing the line: + +| Attribute | Value | +| --- | --- | +| `sql` | The statement, placeholders included | +| `params` | The bound parameters, as a tuple | +| `dialect` | `"sqlite"` or `"postgres"` | +| `duration_ms` | Time the database took, in milliseconds | +| `operation` | What sent it: `"migrate"` for the reconciliation pass and `ferro migrate` | +| `subject` | The table or enum type a pass statement changes, or the step file (`0003_add_slug/01_add_slug.up.sql`) a migration statement comes from; `None` otherwise | +| `connection` | The connection's name | +| `rows` | Rows affected, or `None` for a read | +| `error` | The database's error text, or `None` | + +The logger is the only switch: while `ferro.sql` is not enabled for `DEBUG`, Ferro collects nothing. Ferro installs only a `NullHandler` on its `ferro` logger, which propagates, so your logging configuration (and pytest's `caplog`) decides where the records go. The `ferro` command line installs its own handler, so a data step's `ctx.log.info(...)` lines still print there. + ## See Also - [Schema Management](schema/overview.md) — auto-migrate, migrations and Alembic diff --git a/docs/pages/guide/schema/auto-migrate.md b/docs/pages/guide/schema/auto-migrate.md index f76ac939..198dadfa 100644 --- a/docs/pages/guide/schema/auto-migrate.md +++ b/docs/pages/guide/schema/auto-migrate.md @@ -254,7 +254,7 @@ except ferro.OperationalError as error: changed = {s.subject for s in error.report.statements if s.role == "schema"} ``` -`connect(..., auto_migrate=True)` runs the same pass and returns nothing; its failure carries the same `.report`. The `ferro` logger's debug lines name each statement as it runs, but they are free text: read the report, not the log. +`connect(..., auto_migrate=True)` runs the same pass and returns nothing; its failure carries the same `.report`. Each statement is also a record on the `ferro.sql` logger as it finishes, with its `sql`, `subject` and duration as attributes (see [Logging](../connections.md#logging)); the log is for watching, and the report is still the structured answer. ## Two processes at once diff --git a/src/backend.rs b/src/backend.rs index 2284f206..13cec57c 100644 --- a/src/backend.rs +++ b/src/backend.rs @@ -14,6 +14,7 @@ use std::collections::{HashMap, HashSet}; use std::fmt; use std::sync::atomic::{AtomicU64, AtomicUsize, Ordering}; use std::sync::{Arc, RwLock}; +use std::time::Instant; /// Infer the SQL dialect / backend from a connection-URL scheme. pub fn dialect_from_url(url: &str) -> Result { @@ -791,12 +792,24 @@ impl EngineHandle { } else { "BEGIN" }; - sqlx::query(begin).execute(&mut *conn).await?; + let started = Instant::now(); + let result = sqlx::query(begin) + .execute(&mut *conn) + .await + .map(|done| done.rows_affected()); + observe_rows(begin, Dialect::Sqlite, started, &result); + result?; Ok(EngineConnection::Sqlite(conn)) } BackendPool::Postgres(pool) => { let mut conn = pool.acquire().await?; - sqlx::query("BEGIN").execute(&mut *conn).await?; + let started = Instant::now(); + let result = sqlx::query("BEGIN") + .execute(&mut *conn) + .await + .map(|done| done.rows_affected()); + observe_rows("BEGIN", Dialect::Postgres, started, &result); + result?; Ok(EngineConnection::Postgres(conn)) } } @@ -825,22 +838,22 @@ impl EngineConnection { /// Migration DDL must use this: caching a statement against a schema the /// same migration is about to change would poison the connection. pub async fn execute_sql_unprepared(&mut self, sql: &str) -> Result { - match self { - EngineConnection::Sqlite(conn) => { - let result = sqlx::query(sql) - .persistent(false) - .execute(&mut **conn) - .await?; - Ok(result.rows_affected()) - } - EngineConnection::Postgres(conn) => { - let result = sqlx::query(sql) - .persistent(false) - .execute(&mut **conn) - .await?; - Ok(result.rows_affected()) - } - } + let dialect = self.dialect(); + let started = Instant::now(); + let result = match self { + EngineConnection::Sqlite(conn) => sqlx::query(sql) + .persistent(false) + .execute(&mut **conn) + .await + .map(|done| done.rows_affected()), + EngineConnection::Postgres(conn) => sqlx::query(sql) + .persistent(false) + .execute(&mut **conn) + .await + .map(|done| done.rows_affected()), + }; + observe_rows(sql, dialect, started, &result); + result } /// Fetch without entering the connection's prepared-statement cache — the @@ -851,24 +864,32 @@ impl EngineConnection { sql: &str, values: &[EngineBindValue], ) -> Result, sqlx::Error> { - match self { + let dialect = self.dialect(); + let started = Instant::now(); + let result = match self { EngineConnection::Sqlite(conn) => { let mut query = sqlx::query(sql).persistent(false); for value in values { query = bind_engine_value(query, value); } - let rows = query.fetch_all(&mut **conn).await?; - Ok(rows.iter().map(materialize_engine_row).collect()) + query + .fetch_all(&mut **conn) + .await + .map(|rows| rows.iter().map(materialize_engine_row).collect()) } EngineConnection::Postgres(conn) => { let mut query = sqlx::query(sql).persistent(false); for value in values { query = bind_engine_value(query, value); } - let rows = query.fetch_all(&mut **conn).await?; - Ok(rows.iter().map(materialize_pg_row).collect()) + query + .fetch_all(&mut **conn) + .await + .map(|rows| rows.iter().map(materialize_pg_row).collect()) } - } + }; + observe_fetch(sql, values, dialect, started, &result); + result } pub async fn execute_sql_with_binds( @@ -887,30 +908,44 @@ impl EngineConnection { sql: &str, values: &[EngineBindValue], ) -> Result { - match self { + let dialect = self.dialect(); + let started = Instant::now(); + let result = match self { EngineConnection::Sqlite(conn) => { let mut query = sqlx::query(sql); for value in values { query = bind_engine_value(query, value); } - let result = query.execute(&mut **conn).await?; - Ok(EngineExecuteResult { - rows_affected: result.rows_affected(), - last_insert_id: Some(result.last_insert_rowid()), - }) + query + .execute(&mut **conn) + .await + .map(|done| EngineExecuteResult { + rows_affected: done.rows_affected(), + last_insert_id: Some(done.last_insert_rowid()), + }) } EngineConnection::Postgres(conn) => { let mut query = sqlx::query(sql); for value in values { query = bind_engine_value(query, value); } - let result = query.execute(&mut **conn).await?; - Ok(EngineExecuteResult { - rows_affected: result.rows_affected(), - last_insert_id: None, - }) + query + .execute(&mut **conn) + .await + .map(|done| EngineExecuteResult { + rows_affected: done.rows_affected(), + last_insert_id: None, + }) } - } + }; + crate::sql_log::observe( + sql, + values, + dialect, + started, + result.as_ref().map(|done| Some(done.rows_affected)), + ); + result } pub async fn fetch_all_sql_with_binds( @@ -918,24 +953,32 @@ impl EngineConnection { sql: &str, values: &[EngineBindValue], ) -> Result, sqlx::Error> { - match self { + let dialect = self.dialect(); + let started = Instant::now(); + let result = match self { EngineConnection::Sqlite(conn) => { let mut query = sqlx::query(sql); for value in values { query = bind_engine_value(query, value); } - let rows = query.fetch_all(&mut **conn).await?; - Ok(rows.iter().map(materialize_engine_row).collect()) + query + .fetch_all(&mut **conn) + .await + .map(|rows| rows.iter().map(materialize_engine_row).collect()) } EngineConnection::Postgres(conn) => { let mut query = sqlx::query(sql); for value in values { query = bind_engine_value(query, value); } - let rows = query.fetch_all(&mut **conn).await?; - Ok(rows.iter().map(materialize_pg_row).collect()) + query + .fetch_all(&mut **conn) + .await + .map(|rows| rows.iter().map(materialize_pg_row).collect()) } - } + }; + observe_fetch(sql, values, dialect, started, &result); + result } pub async fn commit(&mut self) -> Result<(), sqlx::Error> { @@ -979,6 +1022,29 @@ impl EngineConnection { } } +/// The statement log's record of an unbound execute that returned `result`'s +/// rows affected. +fn observe_rows(sql: &str, dialect: Dialect, started: Instant, result: &Result) { + crate::sql_log::observe( + sql, + &[], + dialect, + started, + result.as_ref().map(|n| Some(*n)), + ); +} + +/// The statement log's record of a fetch: it reports no rows affected. +fn observe_fetch( + sql: &str, + binds: &[EngineBindValue], + dialect: Dialect, + started: Instant, + result: &Result, sqlx::Error>, +) { + crate::sql_log::observe(sql, binds, dialect, started, result.as_ref().map(|_| None)); +} + fn materialize_engine_row(row: &R) -> EngineRow where R: Row, diff --git a/src/connection.rs b/src/connection.rs index df7d0302..c318bdb2 100644 --- a/src/connection.rs +++ b/src/connection.rs @@ -307,6 +307,7 @@ pub fn connect( let should_select_default = default || is_implicit_default; sqlx::any::install_default_drivers(); + let logged = crate::sql_log::enabled(py)?; pyo3_async_runtimes::tokio::future_into_py(py, async move { if CONNECTION_REGISTRY @@ -361,12 +362,20 @@ pub fn connect( // pass's error carries it. if auto_migrate || opts.updates { let mut report = PassReport::default(); - internal_migrate( - engine_handle.clone(), - opts, - &tracking_schemas, - AutoMigrateDoor::Connect, - &mut report, + crate::sql_log::scope( + logged.then(|| { + crate::sql_log::StatementContext::new( + crate::sql_log::MIGRATE, + connection_name.clone(), + ) + }), + internal_migrate( + engine_handle.clone(), + opts, + &tracking_schemas, + AutoMigrateDoor::Connect, + &mut report, + ), ) .await .map_err(|err| with_pass_report(err, &report))?; diff --git a/src/ddl_exec.rs b/src/ddl_exec.rs index 37def150..7c6daa59 100644 --- a/src/ddl_exec.rs +++ b/src/ddl_exec.rs @@ -17,8 +17,8 @@ //! //! A caller hands [`DdlExecutor::run`] a statement list and the [`Unit`] it //! runs as; the executor owns the rest: the connection, the transaction, the -//! lock-timeout statements, the debug line before each statement, the -//! retries, and which statement failed ([`Failed::index`]). Every statement +//! lock-timeout statements, each statement's subject in the statement log, +//! the retries, and which statement failed ([`Failed::index`]). Every statement //! runs unprepared, so no connection keeps a statement prepared against a //! schema the next migration changes //! (`docs/solutions/patterns/ddl-on-live-engine.md`). @@ -181,8 +181,8 @@ pub enum Unit { Unwrapped, } -/// Whose statements a unit runs: the subject of every statement, and the -/// voice of the debug line logged before it. +/// Whose statements a unit runs: the subject of every statement, in the +/// report and in its statement log record. #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub enum Door<'a> { /// The create or reconciliation pass, on this table or enum type. @@ -200,17 +200,6 @@ impl Door<'_> { role, } } - - /// The debug line logged before `statement` runs: free text, one per - /// statement. What a pass ran is its [`crate::migrate::PassReport`], never - /// this line. - fn log(self, statement: &Statement) { - let (subject, sql) = (statement.subject.as_str(), statement.sql.as_str()); - match self { - Door::Pass(_) => crate::log_debug(format!("ferro auto-migrate: {subject}: {sql}")), - Door::Run(_) => crate::run::log_step_statement(subject, sql), - } - } } /// What a statement the executor sent was for. On the wire (the pass's @@ -246,8 +235,8 @@ pub struct Executed { } impl Executed { - /// Log `sql` as `door`'s, run it unprepared on `conn`, and record it once - /// it succeeded. + /// Run `sql` unprepared on `conn` as `door`'s, its statement log record + /// under `door`'s subject, and record it once it succeeded. /// /// # Errors /// The database error; nothing is recorded. @@ -259,8 +248,9 @@ impl Executed { sql: &str, ) -> Result { let statement = door.statement(role, sql); - door.log(&statement); - let affected = conn.execute_sql_unprepared(sql).await?; + let affected = + crate::sql_log::with_subject(&statement.subject, conn.execute_sql_unprepared(sql)) + .await?; self.statements.push(statement); Ok(affected) } @@ -278,15 +268,16 @@ impl Executed { sql: &str, ) -> Result { let statement = door.statement(role, sql); - door.log(&statement); - let affected = engine.execute_sql_unprepared(sql).await?; + let affected = + crate::sql_log::with_subject(&statement.subject, engine.execute_sql_unprepared(sql)) + .await?; self.statements.push(statement); Ok(affected) } - /// Log the read `sql` as `door`'s, run it unprepared on a connection out - /// of `engine`'s pool, and record it as [`Role::Probe`] once it - /// succeeded. + /// Run the read `sql` unprepared as `door`'s on a connection out of + /// `engine`'s pool, its statement log record under `door`'s subject, and + /// record it as [`Role::Probe`] once it succeeded. /// /// # Errors /// The pool's or the database's error; nothing is recorded. @@ -297,8 +288,9 @@ impl Executed { sql: &str, ) -> Result, sqlx::Error> { let statement = door.statement(Role::Probe, sql); - door.log(&statement); - let rows = engine.fetch_all_sql_unprepared(sql).await?; + let rows = + crate::sql_log::with_subject(&statement.subject, engine.fetch_all_sql_unprepared(sql)) + .await?; self.statements.push(statement); Ok(rows) } diff --git a/src/ferro/__init__.py b/src/ferro/__init__.py index d8895665..1e540208 100644 --- a/src/ferro/__init__.py +++ b/src/ferro/__init__.py @@ -62,16 +62,10 @@ parse_ddl_lock_timeout, ) -# Set up the Ferro logger -_logger = logging.getLogger("ferro") -# Only add a handler if none exists (to avoid duplicate logs) -if not _logger.handlers: - _handler = logging.StreamHandler() - _handler.setFormatter(logging.Formatter("%(name)s: %(levelname)s: %(message)s")) - _logger.addHandler(_handler) - _logger.setLevel(logging.INFO) - # Prevent propagation to root logger to avoid duplicate messages - _logger.propagate = False +# A library installs no output of its own: the `ferro` logger (and the +# statement log on `ferro.sql` beneath it) propagates to whatever logging the +# application configures. The `ferro` CLI, an application, installs its own. +logging.getLogger("ferro").addHandler(logging.NullHandler()) _RESOLVED_MODELSET_LOCK = threading.Lock() diff --git a/src/ferro/_sql_log.py b/src/ferro/_sql_log.py new file mode 100644 index 00000000..065190a6 --- /dev/null +++ b/src/ferro/_sql_log.py @@ -0,0 +1,70 @@ +"""The statement log: one record on ``ferro.sql`` per statement ferro sends. + +The Rust engine measures each statement as it finishes and hands its data to +[`emit`][ferro._sql_log.emit], which writes the record. Rust formats nothing; +this module is the one place a record's message and attributes are built. +""" + +from __future__ import annotations + +import logging +from typing import Final + +LOGGER: Final = logging.getLogger("ferro.sql") +"""The statement log's logger. Set it to `DEBUG` to see every statement.""" + + +class _Redacted: + """The stand-in for a secret parameter in a record.""" + + __slots__ = () + + def __repr__(self) -> str: + return "***" + + __str__ = __repr__ + + +REDACTED: Final = _Redacted() +"""A secret parameter as a record shows it: its `repr` and `str` are `***`.""" + + +def emit(record: dict[str, object]) -> None: + """Write one statement's record on `ferro.sql` at `DEBUG`. + + The message is ` params= ms`, followed by + ` failed: ` when the statement raised. Every field except `mask` + is also an attribute of the `LogRecord`, with each masked parameter + replaced by [`REDACTED`][ferro._sql_log.REDACTED]. + + Args: + record: The statement's data, as the engine hands it over: `sql`, + `params` (a tuple, `None` in each masked position), `mask` (a + tuple of booleans, `True` where the parameter is a secret), + `dialect`, `duration_ms`, `operation`, `subject`, `connection`, + `rows` (rows affected, or `None` for a fetch) and `error` (the + database's error text, or `None`). + """ + mask = record["mask"] + params = tuple( + REDACTED if masked else value + for value, masked in zip(record["params"], mask, strict=True) # type: ignore[call-overload] + ) + error = record["error"] + message = f"{record['sql']} params={params!r} {record['duration_ms']:.1f}ms" + if error is not None: + message += f" failed: {error}" + LOGGER.debug( + message, + extra={ + "sql": record["sql"], + "params": params, + "dialect": record["dialect"], + "duration_ms": record["duration_ms"], + "operation": record["operation"], + "subject": record["subject"], + "connection": record["connection"], + "rows": record["rows"], + "error": error, + }, + ) diff --git a/src/ferro/cli/__init__.py b/src/ferro/cli/__init__.py index bc4a7024..5c829982 100644 --- a/src/ferro/cli/__init__.py +++ b/src/ferro/cli/__init__.py @@ -20,8 +20,10 @@ A bad flag or a missing ``cli`` extra exits :data:`exit_codes.USAGE`. """ +import logging import sys -from collections.abc import Sequence +from collections.abc import Iterator, Sequence +from contextlib import contextmanager from dataclasses import dataclass from pathlib import Path from typing import TYPE_CHECKING, Annotated, Any @@ -79,13 +81,38 @@ def main(argv: Sequence[str] | None = None) -> int: tokens = list(sys.argv[1:] if argv is None else argv) try: - result = _app()(tokens) + with _ferro_log_to_stderr(): + result = _app()(tokens) except cyclopts.CycloptsError: # cyclopts has already printed the error, naming the bad token. return exit_codes.USAGE return exit_codes.OK if result is None else int(result) +@contextmanager +def _ferro_log_to_stderr() -> Iterator[None]: + """Print the ``ferro`` logger's ``INFO`` lines to stderr while a verb runs. + + The library installs only a ``NullHandler``; the command is an + application, so it shows what a data step's ``ctx.log.info(...)`` says. + The handler and level are put back afterwards, so calling :func:`main` + in-process leaves the caller's logging as it found it. + """ + logger = logging.getLogger("ferro") + handler = logging.StreamHandler(sys.stderr) + handler.setLevel(logging.INFO) + handler.setFormatter(logging.Formatter("%(name)s: %(levelname)s: %(message)s")) + level = logger.level + logger.addHandler(handler) + if logger.getEffectiveLevel() > logging.INFO: + logger.setLevel(logging.INFO) + try: + yield + finally: + logger.removeHandler(handler) + logger.setLevel(level) + + _built: "App | None" = None diff --git a/src/lib.rs b/src/lib.rs index 57b96ab9..f9905af9 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -22,6 +22,7 @@ mod run; mod schema; mod schema_bind; mod session_settings; +mod sql_log; mod state; use pyo3::prelude::*; diff --git a/src/migrate.rs b/src/migrate.rs index 0c278f07..f6d433c8 100644 --- a/src/migrate.rs +++ b/src/migrate.rs @@ -1216,9 +1216,16 @@ pub fn migrate( let opts = MigrateOptions::laddered(updates, destructive) .with_ddl_lock_timeout_seconds(ddl_lock_timeout_s)? .with_lock_timeout_seconds(lock_timeout_s)?; + let logged = crate::sql_log::enabled(py)?; pyo3_async_runtimes::tokio::future_into_py(py, async move { - let engine = engine_for_connection(using)?; - run_pass_for_python(engine, opts, &tracking_schemas, AutoMigrateDoor::Migrate).await + let (connection, engine) = crate::state::connection_for_route(using)?; + crate::sql_log::scope( + logged.then(|| { + crate::sql_log::StatementContext::new(crate::sql_log::MIGRATE, connection) + }), + run_pass_for_python(engine, opts, &tracking_schemas, AutoMigrateDoor::Migrate), + ) + .await }) } diff --git a/src/migrations_ffi.rs b/src/migrations_ffi.rs index db541a00..8f542964 100644 --- a/src/migrations_ffi.rs +++ b/src/migrations_ffi.rs @@ -435,12 +435,35 @@ pub fn _tracking_tables_for( using: Option, schema: Option, ) -> PyResult> { + let logged = crate::sql_log::enabled(py)?; pyo3_async_runtimes::tokio::future_into_py(py, async move { - let engine = crate::state::engine_for_connection(using)?; - to_json(&crate::run::tracking_tables_for(&engine, schema.as_deref()).await?) + let (connection, engine) = crate::state::connection_for_route(using)?; + crate::sql_log::scope(run_context(logged, &connection), async { + to_json(&crate::run::tracking_tables_for(&engine, schema.as_deref()).await?) + }) + .await }) } +/// A run's statement log context on `connection` when the log is on. +fn run_context(logged: bool, connection: &str) -> Option { + logged.then(|| crate::sql_log::StatementContext::new(crate::sql_log::MIGRATE, connection)) +} + +/// `future_into_py` for a run's work on `connection`: every statement `fut` +/// sends is a statement log record of `migrate` when the log is on. +/// +/// # Errors +/// The `PyErr` from asking whether the log is on. +fn logged<'py, F, T>(py: Python<'py>, connection: &str, fut: F) -> PyResult> +where + F: std::future::Future> + Send + 'static, + T: for<'a> IntoPyObject<'a> + Send + 'static, +{ + let context = run_context(crate::sql_log::enabled(py)?, connection); + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(context, fut)) +} + /// A value as the Python object its JSON reads as (`dict`, `list`, ...). fn to_py(py: Python<'_>, value: &T) -> PyResult> { let json = to_json(value)?; @@ -561,12 +584,17 @@ pub fn _open_tracked( ddl_lock_timeout_s: f64, ) -> PyResult> { let ddl = crate::ddl_exec::DdlExecutor::from_seconds(ddl_lock_timeout_s)?; + let logged = crate::sql_log::enabled(py)?; pyo3_async_runtimes::tokio::future_into_py(py, async move { - let engine = crate::state::engine_for_connection(using)?; - let tracked = - crate::run::Tracked::open(engine, tracking_schema, Path::new(&directory)).await?; + let (connection, engine) = crate::state::connection_for_route(using)?; + let tracked = crate::sql_log::scope( + run_context(logged, &connection), + crate::run::Tracked::open(engine, tracking_schema, Path::new(&directory)), + ) + .await?; Ok(TrackedDatabase { inner: Arc::new(tracked), + connection: connection.into(), ddl: Arc::new(ddl), }) }) @@ -807,6 +835,8 @@ mod reads { #[pyclass(frozen, module = "ferro._core")] pub struct TrackedDatabase { inner: Arc, + /// The connection's name, the `connection` of its statement log records. + connection: Arc, ddl: Arc, } @@ -854,7 +884,11 @@ impl TrackedDatabase { /// Whether any run holds the run lock, asked without taking it. fn lock_held<'py>(&self, py: Python<'py>) -> PyResult> { let tracked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { tracked.lock_held().await }) + logged( + py, + &self.connection, + async move { tracked.lock_held().await }, + ) } /// `ferro migrate status`'s document: every migration's steps, the @@ -897,7 +931,7 @@ impl TrackedDatabase { .map(|declared_kind| declared_kinds(self.inner.inheritance_data_steps(), declared_kind)) .transpose()?; let tracked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { let plan = match &kinds { Some(kinds) => { tracked @@ -934,6 +968,7 @@ impl TrackedDatabase { ) -> PyResult { Ok(LockScope { tracked: Arc::clone(&self.inner), + connection: Arc::clone(&self.connection), ddl: Arc::clone(&self.ddl), timeout: lock_timeout(timeout_s)?, on_wait, @@ -949,6 +984,7 @@ impl TrackedDatabase { fn _locked_unacquired_for_test(&self) -> LockScope { LockScope { tracked: Arc::clone(&self.inner), + connection: Arc::clone(&self.connection), ddl: Arc::clone(&self.ddl), timeout: std::time::Duration::ZERO, on_wait: None, @@ -975,6 +1011,7 @@ fn dialect_name(dialect: Dialect) -> &'static str { #[pyclass(frozen, module = "ferro._core")] pub struct LockScope { tracked: Arc, + connection: Arc, ddl: Arc, timeout: std::time::Duration, on_wait: Option>, @@ -1003,7 +1040,8 @@ impl LockScope { let on_wait = self.on_wait.as_ref().map(|c| c.clone_ref(py)); let (timeout, unacquired, classes) = (self.timeout, self.unacquired, self.classes); let entered = Arc::clone(&self.entered); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let connection = Arc::clone(&self.connection); + logged(py, &self.connection, async move { let locked = if unacquired { tracked.lock_unacquired_for_test(classes).await? } else { @@ -1025,7 +1063,11 @@ impl LockScope { }; let locked = Arc::new(locked); *entered.lock().map_err(|_| scope_poisoned())? = Some(Arc::clone(&locked)); - Ok(LockedDatabase { inner: locked, ddl }) + Ok(LockedDatabase { + inner: locked, + connection, + ddl, + }) }) } @@ -1036,7 +1078,7 @@ impl LockScope { _exc: &Bound<'py, pyo3::types::PyTuple>, ) -> PyResult> { let locked = self.entered.lock().map_err(|_| scope_poisoned())?.take(); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { if let Some(locked) = locked { locked.release().await?; } @@ -1122,6 +1164,7 @@ fn record_kind(kind: &str) -> PyResult { #[pyclass(frozen, module = "ferro._core")] pub struct LockedDatabase { inner: Arc, + connection: Arc, ddl: Arc, } @@ -1176,10 +1219,9 @@ impl LockedDatabase { /// Whether any run holds the run lock (this one does). fn lock_held<'py>(&self, py: Python<'py>) -> PyResult> { let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py( - py, - async move { locked.tracked().lock_held().await }, - ) + logged(py, &self.connection, async move { + locked.tracked().lock_held().await + }) } /// `ferro migrate status`'s document, as of the records read under the @@ -1213,7 +1255,7 @@ impl LockedDatabase { .unwrap_or_default(); let order_keys = order_keys_arg(order_keys)?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { let plan = locked .tracked() .plan(direction, allow_ahead, order_keys.as_ref()) @@ -1242,7 +1284,7 @@ impl LockedDatabase { ) -> PyResult> { let kinds = declared_kinds(self.inner.tracked().inheritance_data_steps(), declared_kind)?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { let inherited = locked.inherit(&kinds).await?; to_py_attached(&inherited) }) @@ -1268,7 +1310,7 @@ impl LockedDatabase { let planned = Arc::clone(owned(&step, &self.inner)?); let down = step.down; let (locked, ddl) = (Arc::clone(&self.inner), Arc::clone(&self.ddl)); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { // A callback that raises is the caller's bug: its first error is // raised once the step has settled its record (stopping mid-step // would leave the record started with nothing running). @@ -1303,7 +1345,7 @@ impl LockedDatabase { let standing = step.standing.clone(); let kind = record_kind(kind)?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.start(&planned, kind, standing.as_ref()).await }) } @@ -1351,7 +1393,7 @@ impl LockedDatabase { let position = position(cursor, rows_done)?; let slot = tx.map(|route| transaction_slot(route.get())).transpose()?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.finish(&planned, ms, slot.as_ref(), position).await }) } @@ -1371,7 +1413,7 @@ impl LockedDatabase { let planned = Arc::clone(owned(&step, &self.inner)?); let position = position(cursor, rows_done)?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.fail(&planned, ms, error, position).await }) } @@ -1389,7 +1431,7 @@ impl LockedDatabase { let planned = Arc::clone(owned(&step, &self.inner)?); let position = (cursor, rows(rows_done)?); let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.fail_revert(&planned, error, position).await }) } @@ -1404,7 +1446,7 @@ impl LockedDatabase { let planned = Arc::clone(owned(&step, &self.inner)?); let slot = transaction_slot(tx.get())?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.remove(&planned, &slot).await }) } @@ -1440,7 +1482,7 @@ impl LockedDatabase { planned_here(plan.owner, &self.inner, "baseline")?; let plan = Arc::clone(&plan.plan); let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.write_baseline(&plan, &kinds).await }) } @@ -1449,10 +1491,9 @@ impl LockedDatabase { /// of each record removed (empty when there was no baseline). fn remove_baseline<'py>(&self, py: Python<'py>) -> PyResult> { let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py( - py, - async move { locked.remove_baseline().await }, - ) + logged(py, &self.connection, async move { + locked.remove_baseline().await + }) } /// Plan `ferro migrate rerecord `: `mode` is `"record"`, @@ -1489,7 +1530,7 @@ impl LockedDatabase { planned_here(action.owner, &self.inner, "rerecord")?; let action = Arc::clone(&action.action); let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.rerecord(&action, kind).await }) } @@ -1498,7 +1539,7 @@ impl LockedDatabase { /// dropped network connection would. Test-only. fn _close_lock_connection_for_test<'py>(&self, py: Python<'py>) -> PyResult> { let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.close_lock_connection_for_test().await; Ok(()) }) @@ -1529,7 +1570,7 @@ impl LockedDatabase { let position = batch_position(cursor, rows_done)?; let slot = transaction_slot(tx.get())?; let locked = Arc::clone(&self.inner); - pyo3_async_runtimes::tokio::future_into_py(py, async move { + logged(py, &self.connection, async move { locked.advance(&planned, position, &slot, reverting).await }) } diff --git a/src/run.rs b/src/run.rs index 22a55b18..33435216 100644 --- a/src/run.rs +++ b/src/run.rs @@ -1039,7 +1039,6 @@ pub async fn ensure_tracking_tables( .map_err(|e| db_error("creating the tracking tables", e))?; let result: Result<(), sqlx::Error> = async { for ddl in tracking_ddl(dialect, &tracking) { - crate::log_debug(format!("ferro migrate: {ddl}")); conn.execute_sql_unprepared(&ddl).await?; } let format_table = tracking.table(FORMAT_TABLE); @@ -1057,7 +1056,6 @@ pub async fn ensure_tracking_tables( .is_empty() { let alter = format!("ALTER TABLE {} ADD COLUMN {ddl}", tracking.table(table)); - crate::log_debug(format!("ferro migrate: {alter}")); conn.execute_sql_unprepared(&alter).await?; } } @@ -1564,10 +1562,6 @@ impl StepFailure { } } -pub(crate) fn log_step_statement(file: &str, statement: &str) { - crate::log_debug(format!("ferro migrate: {file}: {statement}")); -} - async fn run_statements( conn: &mut EngineConnection, executed: &mut Executed, diff --git a/src/schema.rs b/src/schema.rs index db7745ee..5907a38d 100644 --- a/src/schema.rs +++ b/src/schema.rs @@ -6,7 +6,7 @@ use crate::backend::EngineHandle; use crate::ddl_exec::{DdlError, DdlExecutor, Door, Failed, Unit}; use crate::migrate::{PassReport, pass_attempt_warning, pass_lock_timeout_error}; -use crate::state::{Dialect, MODEL_REGISTRY, engine_for_connection}; +use crate::state::{Dialect, MODEL_REGISTRY}; use ferro_migrate::Subject; use ferro_migrate::plan::{ hint_refusal_warning, pending_table_rename_warning, refuse_hints, table_rename_hint, @@ -458,16 +458,22 @@ pub fn create_tables( let opts = crate::migrate::MigrateOptions::laddered(false, false) .with_ddl_lock_timeout_seconds(ddl_lock_timeout_s)? .with_lock_timeout_seconds(lock_timeout_s)?; + let logged = crate::sql_log::enabled(py)?; pyo3_async_runtimes::tokio::future_into_py(py, async move { - let engine = engine_for_connection(using)?; + let (connection, engine) = crate::state::connection_for_route(using)?; // `create_tables()` is the create pass on its own (no `updates`): // nothing reconciles an existing table afterwards, so a declaration // on one is reported. It shares the lock-then-guard path. - crate::migrate::run_pass_for_python( - engine, - opts, - &tracking_schemas, - crate::migrate::AutoMigrateDoor::CreateTables, + crate::sql_log::scope( + logged.then(|| { + crate::sql_log::StatementContext::new(crate::sql_log::MIGRATE, connection) + }), + crate::migrate::run_pass_for_python( + engine, + opts, + &tracking_schemas, + crate::migrate::AutoMigrateDoor::CreateTables, + ), ) .await }) diff --git a/src/sql_log.rs b/src/sql_log.rs new file mode 100644 index 00000000..cd58affe --- /dev/null +++ b/src/sql_log.rs @@ -0,0 +1,336 @@ +//! The statement log (ADR-0057): every statement ferro sends, one record on +//! the `ferro.sql` logger as it finishes. +//! +//! ```text +//! >>> logging.getLogger("ferro.sql").setLevel(logging.DEBUG) +//! >>> await ferro.migrate() +//! ferro.sql DEBUG ALTER TABLE "author" ADD COLUMN "bio" varchar params=() 0.8ms +//! ``` +//! +//! The logger is the only switch. An FFI entry asks [`enabled`] once, while +//! it holds the GIL, and opens a [`scope`] only when the answer is yes. The +//! engine's execute and fetch layer (`crate::backend`), which every statement +//! passes through, calls [`observe`] after each statement; outside a scope +//! that is a task-local read and nothing more. Inside one it takes the GIL +//! once and hands the statement's data to `ferro._sql_log.emit`, the one +//! place a record's message is built: Rust formats nothing. +//! +//! The emitter raising is an error of the operation, not something to +//! swallow: the scope keeps the first such error and returns it in place of +//! the operation's result once the operation finishes. + +use crate::backend::EngineBindValue; +use ferro_ddl_lowering::Dialect; +use pyo3::prelude::*; +use pyo3::sync::PyOnceLock; +use pyo3::types::{PyBytes, PyDict, PyTuple}; +use std::future::Future; +use std::sync::{Arc, Mutex}; +use std::time::Instant; + +/// `logging.DEBUG`. +const DEBUG: i32 = 10; + +/// The `operation` of every statement the reconciliation pass or a run +/// sends. +pub const MIGRATE: &str = "migrate"; + +static LOGGER: PyOnceLock> = PyOnceLock::new(); +static EMITTER_MODULE: PyOnceLock> = PyOnceLock::new(); +static UUID_CLASS: PyOnceLock> = PyOnceLock::new(); + +/// Whether `ferro.sql` is enabled for `DEBUG`: the statement log's one +/// switch, asked once per FFI entry. +/// +/// # Errors +/// The `PyErr` from importing `logging` or asking the logger. +pub fn enabled(py: Python<'_>) -> PyResult { + LOGGER + .get_or_try_init(py, || -> PyResult> { + Ok(py + .import("logging")? + .call_method1("getLogger", ("ferro.sql",))? + .unbind()) + })? + .bind(py) + .call_method1("isEnabledFor", (DEBUG,))? + .extract() +} + +/// What every record written inside one [`scope`] shares. +#[derive(Clone, Debug)] +pub struct StatementContext { + /// What sent the statements: `"migrate"` for the reconciliation pass and + /// a run. + pub operation: &'static str, + /// The connection's name (`"default"` unless named). + pub connection: String, + /// The table, enum type or step file the statement belongs to, when + /// there is one (see [`with_subject`]). + pub subject: Option, + /// Bound values a record shows as `***`. + pub secret_values: Vec, +} + +impl StatementContext { + /// A context for `operation` on `connection`, with no subject and no + /// secret values. + pub fn new(operation: &'static str, connection: impl Into) -> Self { + Self { + operation, + connection: connection.into(), + subject: None, + secret_values: Vec::new(), + } + } +} + +/// An open scope: its context, and the first error the emitter raised in it +/// (shared with every [`with_subject`] nested inside). +#[derive(Debug)] +struct Active { + context: StatementContext, + failure: Arc>>, +} + +impl Active { + fn fail(&self, err: PyErr) { + match self.failure.lock() { + Ok(mut slot) => { + if slot.is_none() { + *slot = Some(err); + } + } + // A poisoned slot cannot hold the error; it must still be seen. + Err(_) => Python::attach(|py| err.write_unraisable(py, None)), + } + } + + fn take_failure(&self) -> Option { + match self.failure.lock() { + Ok(mut slot) => slot.take(), + Err(poisoned) => poisoned.into_inner().take(), + } + } +} + +tokio::task_local! { + static ACTIVE: Option>; +} + +fn current() -> Option> { + ACTIVE.try_with(Clone::clone).ok().flatten() +} + +/// Run `fut` with the statement log open under `ctx`; with `None` (the log +/// is off) run it as it is. Every statement `fut` sends on this task is +/// written under `ctx`. +/// +/// # Errors +/// `fut`'s error; when `fut` succeeded, the first error the emitter raised +/// while it ran. +pub async fn scope(ctx: Option, fut: F) -> PyResult +where + F: Future>, +{ + let Some(context) = ctx else { + return fut.await; + }; + let active = Arc::new(Active { + context, + failure: Arc::new(Mutex::new(None)), + }); + let result = ACTIVE.scope(Some(Arc::clone(&active)), fut).await; + match (result, active.take_failure()) { + (result, None) => result, + (Ok(_), Some(failure)) => Err(failure), + (Err(err), Some(failure)) => { + // The operation's own error is the answer; the emitter's still + // reaches the reader. + Python::attach(|py| failure.write_unraisable(py, None)); + Err(err) + } + } +} + +/// Run `fut` with the open scope's subject set to `subject` (a pass's table, +/// a run's `NNNN_name/`). Outside a scope it is `fut` itself. +pub async fn with_subject(subject: &str, fut: F) -> F::Output { + match current() { + Some(active) => { + let child = Active { + context: StatementContext { + subject: Some(subject.to_string()), + ..active.context.clone() + }, + failure: Arc::clone(&active.failure), + }; + ACTIVE.scope(Some(Arc::new(child)), fut).await + } + None => fut.await, + } +} + +/// Write one finished statement to the statement log: `sql` with `binds`, +/// on `dialect`, sent at `started`, with what it returned (rows affected, +/// `None` for a fetch, or the database's error). A no-op outside a scope. +pub fn observe( + sql: &str, + binds: &[EngineBindValue], + dialect: Dialect, + started: Instant, + outcome: Result, &sqlx::Error>, +) { + let Some(active) = current() else { + return; + }; + let duration_ms = started.elapsed().as_secs_f64() * 1000.0; + let written = Python::attach(|py| { + emit( + py, + &active.context, + sql, + binds, + dialect, + duration_ms, + outcome, + ) + }); + if let Err(err) = written { + active.fail(err); + } +} + +/// Which of `binds` are secret: equal to one of `secrets`. +fn mask_of(binds: &[EngineBindValue], secrets: &[EngineBindValue]) -> Vec { + binds.iter().map(|bind| secrets.contains(bind)).collect() +} + +fn dialect_name(dialect: Dialect) -> &'static str { + match dialect { + Dialect::Postgres => "postgres", + Dialect::Sqlite => "sqlite", + } +} + +fn bind_to_py<'py>(py: Python<'py>, bind: &EngineBindValue) -> PyResult> { + use pyo3::IntoPyObjectExt; + match bind { + EngineBindValue::Bool(value) => value.into_bound_py_any(py), + EngineBindValue::I64(value) => value.into_bound_py_any(py), + EngineBindValue::F64(value) => value.into_bound_py_any(py), + EngineBindValue::String(value) => value.into_bound_py_any(py), + EngineBindValue::Bytes(value) => Ok(PyBytes::new(py, value).into_any()), + EngineBindValue::Uuid(value) => UUID_CLASS + .get_or_try_init(py, || -> PyResult> { + Ok(py.import("uuid")?.getattr("UUID")?.unbind()) + })? + .bind(py) + .call1((value.to_string(),)), + EngineBindValue::Null(_) => Ok(py.None().into_bound(py)), + } +} + +/// Hand one statement's data to `ferro._sql_log.emit`, looked up on its +/// module at each call so the emitter is always the module's current one. +fn emit( + py: Python<'_>, + context: &StatementContext, + sql: &str, + binds: &[EngineBindValue], + dialect: Dialect, + duration_ms: f64, + outcome: Result, &sqlx::Error>, +) -> PyResult<()> { + let mask = mask_of(binds, &context.secret_values); + let params = binds + .iter() + .zip(&mask) + .map(|(bind, &masked)| { + if masked { + Ok(py.None().into_bound(py)) + } else { + bind_to_py(py, bind) + } + }) + .collect::>>()?; + let (rows, error) = match outcome { + Ok(rows) => (rows, None), + Err(err) => (None, Some(err.to_string())), + }; + let record = PyDict::new(py); + record.set_item("sql", sql)?; + record.set_item("params", PyTuple::new(py, params)?)?; + record.set_item("mask", PyTuple::new(py, mask)?)?; + record.set_item("dialect", dialect_name(dialect))?; + record.set_item("duration_ms", duration_ms)?; + record.set_item("operation", context.operation)?; + record.set_item("subject", context.subject.as_deref())?; + record.set_item("connection", context.connection.as_str())?; + record.set_item("rows", rows)?; + record.set_item("error", error)?; + EMITTER_MODULE + .get_or_try_init(py, || -> PyResult> { + Ok(py.import("ferro._sql_log")?.into_any().unbind()) + })? + .bind(py) + .getattr("emit")? + .call1((record,))?; + Ok(()) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::backend::NullKind; + + #[test] + fn a_bind_is_masked_when_it_equals_a_secret_value() { + let secret = EngineBindValue::String("hunter2".into()); + let binds = [ + EngineBindValue::I64(7), + secret.clone(), + EngineBindValue::Null(NullKind::String), + ]; + assert_eq!(mask_of(&binds, &[secret]), vec![false, true, false]); + assert_eq!(mask_of(&binds, &[]), vec![false, false, false]); + } + + #[tokio::test] + async fn outside_a_scope_there_is_no_context_and_observe_does_nothing() { + assert!(current().is_none()); + // No scope: observe returns before touching Python. + observe("SELECT 1", &[], Dialect::Sqlite, Instant::now(), Ok(None)); + let ran = scope(None, async { Ok::<_, PyErr>(current().is_none()) }).await; + assert!(ran.is_ok_and(|none| none)); + } + + #[tokio::test] + async fn with_subject_names_the_statements_inside_it_and_no_others() { + let seen = scope(Some(StatementContext::new("migrate", "default")), async { + let before = current().and_then(|a| a.context.subject.clone()); + let inside = with_subject("author", async { + current().and_then(|a| a.context.subject.clone()) + }) + .await; + let after = current().and_then(|a| a.context.subject.clone()); + let connection = current().map(|a| a.context.connection.clone()); + Ok::<_, PyErr>((before, inside, after, connection)) + }) + .await; + let (before, inside, after, connection) = match seen { + Ok(seen) => seen, + Err(err) => panic!("scope failed: {err}"), + }; + assert_eq!(before, None); + assert_eq!(inside.as_deref(), Some("author")); + assert_eq!(after, None); + assert_eq!(connection.as_deref(), Some("default")); + } + + #[tokio::test] + async fn with_subject_outside_a_scope_opens_none() { + let inside = with_subject("author", async { current().is_none() }).await; + assert!(inside); + } +} diff --git a/tests/conftest.py b/tests/conftest.py index b7614eca..c1ab045c 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -1,4 +1,5 @@ import asyncio +import logging import os import sys import uuid @@ -354,3 +355,31 @@ def _ferro_registry_isolation(): # keep in agreement by convention: function-local models drop with their # envelope + fingerprint entries, module-scope state survives. REGISTRY.restore(snapshot) + + +class _StatementRecords(logging.Handler): + """Keeps every record it handles, in order.""" + + def __init__(self) -> None: + super().__init__(level=logging.DEBUG) + self.records: list[logging.LogRecord] = [] + + def emit(self, record: logging.LogRecord) -> None: + self.records.append(record) + + +@pytest.fixture +def statement_records() -> Iterator[list[logging.LogRecord]]: + """The statement log of this test: every record on ``ferro.sql``, in the + order the statements finished, with ``ferro.sql`` at ``DEBUG`` for the + test's duration.""" + logger = logging.getLogger("ferro.sql") + handler = _StatementRecords() + level = logger.level + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + try: + yield handler.records + finally: + logger.removeHandler(handler) + logger.setLevel(level) diff --git a/tests/test_ddl_lock_timeout.py b/tests/test_ddl_lock_timeout.py index bf92389f..96310439 100644 --- a/tests/test_ddl_lock_timeout.py +++ b/tests/test_ddl_lock_timeout.py @@ -18,7 +18,6 @@ from __future__ import annotations import asyncio -import logging import threading import time from typing import Annotated, Any @@ -59,31 +58,6 @@ ) -class _Collect(logging.Handler): - def __init__(self) -> None: - super().__init__(level=logging.DEBUG) - self.messages: list[str] = [] - - def emit(self, record: logging.LogRecord) -> None: - self.messages.append(record.getMessage()) - - -@pytest.fixture -def ferro_log(): - """Every message on the ``ferro`` logger (which does not propagate to - pytest's capture), as executed statements are logged before they run.""" - logger = logging.getLogger("ferro") - handler = _Collect() - level = logger.level - logger.addHandler(handler) - logger.setLevel(logging.DEBUG) - try: - yield handler.messages - finally: - logger.removeHandler(handler) - logger.setLevel(level) - - def _postgres_only(db) -> None: if db.backend != "postgres": pytest.skip("the DDL lock timeout is Postgres-only") @@ -300,7 +274,7 @@ async def test_a_down_waits_under_the_same_timeout(project, pkg, db): ) @pytest.mark.parametrize("no_transaction", [False, True], ids=["transaction", "none"]) async def test_the_step_runs_under_the_configured_timeout_and_zero_sets_none( - project, pkg, db, ferro_log, extra, shown, no_transaction + project, pkg, db, statement_records, extra, shown, no_transaction ): _postgres_only(db) settings, database = await _project(project, pkg, db, extra) @@ -317,7 +291,9 @@ async def test_the_step_runs_under_the_configured_timeout_and_zero_sets_none( assert report.refusal is None assert db.rows('SELECT v FROM "seen"') == [(shown,)] if shown == "0": - assert not [m for m in ferro_log if "SET" in m and "lock_timeout" in m] + assert not [ + r for r in statement_records if "SET" in r.sql and "lock_timeout" in r.sql + ] else: ms = {"5s": 5000, "1s": 1000}[shown] expected = ( @@ -325,8 +301,9 @@ async def test_the_step_runs_under_the_configured_timeout_and_zero_sets_none( if no_transaction else f"SET LOCAL lock_timeout = '{ms}ms'" ) - assert any(m.endswith(expected) for m in ferro_log) - assert any(m.endswith("RESET lock_timeout") for m in ferro_log) == ( + step = "0003_seen/01_seen.up.sql" + assert (step, expected) in [(r.subject, r.sql) for r in statement_records] + assert any(r.sql == "RESET lock_timeout" for r in statement_records) == ( no_transaction ) @@ -345,7 +322,7 @@ async def test_zero_waits_for_the_lock_without_a_retry(project, pkg, db): async def test_sqlite_sets_nothing_and_runs_the_file_as_written( - project, pkg, db, ferro_log + project, pkg, db, statement_records ): if db.backend != "sqlite": pytest.skip("the SQLite half") @@ -355,12 +332,16 @@ async def test_sqlite_sets_nothing_and_runs_the_file_as_written( report, _ = await _up(settings, database, db) assert report.refusal is None - executed = [m for m in ferro_log if m.startswith("ferro migrate: 0003_")] + executed = [ + r.sql + for r in statement_records + if r.subject == "0003_add_slug/01_add_slug.up.sql" + ] assert executed == [ - 'ferro migrate: 0003_add_slug/01_add_slug.up.sql: INSERT INTO "attempt_log" VALUES (1)', - 'ferro migrate: 0003_add_slug/01_add_slug.up.sql: ALTER TABLE "author" ADD COLUMN "slug" text', + 'INSERT INTO "attempt_log" VALUES (1)', + 'ALTER TABLE "author" ADD COLUMN "slug" text', ] - assert not [m for m in ferro_log if "lock_timeout" in m] + assert not [r for r in statement_records if "lock_timeout" in r.sql] # -- the reconciliation pass --------------------------------------------------------------- diff --git a/tests/test_statement_log.py b/tests/test_statement_log.py new file mode 100644 index 00000000..d8eea4c7 --- /dev/null +++ b/tests/test_statement_log.py @@ -0,0 +1,351 @@ +# ruff: noqa: F811 - pytest fixtures imported from a sibling module are redefined as arguments +"""The statement log on migration DDL (#764, ADR-0057). + +```python +logging.getLogger("ferro.sql").setLevel(logging.DEBUG) +report = await ferro.migrate() +# ferro.sql DEBUG CREATE TABLE "post" (...) params=() 1.2ms +# ferro.sql DEBUG ALTER TABLE "author" ADD COLUMN "bio" varchar params=() 0.8ms +``` + +Every statement the reconciliation pass or a run sends is one record on +``ferro.sql`` as it finishes, carrying ``sql``, ``params``, ``dialect``, +``duration_ms``, ``operation``, ``subject``, ``connection``, ``rows`` and +``error``. The logger is the only switch: with ``ferro.sql`` off, nothing is +collected and the emitter is never called. +""" + +from __future__ import annotations + +import logging +from typing import Annotated + +import pytest + +import ferro +import ferro._sql_log +from ferro import Model +from ferro.base import FerroField +from ferro.migrations.testing import harness +from tests.test_migrate_new import ( # noqa: F401 - fixtures + pkg, + project, + write_models, +) +from tests.test_migrate_up import ( # noqa: F401 - fixtures + configure, + db, + migrations, + new, + sql_step, +) + +pytestmark = pytest.mark.backend_matrix + +RECORD_ATTRIBUTES = ( + "sql", + "params", + "dialect", + "duration_ms", + "operation", + "subject", + "connection", + "rows", + "error", +) + + +# -- the reconciliation pass ---------------------------------------------------------- + + +@pytest.fixture +def _fresh(clean_registry): + yield + ferro.reset_engine() + + +def _declare_author(*, bio: bool) -> None: + if bio: + + class Author(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str + bio: str | None = None + + else: + + class Author(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str + + +def _rewind() -> None: + from ferro.registry import REGISTRY + + ferro.reset_engine() + ferro.clear_registry() + REGISTRY.reset_for_test() + + +def _pass_records(records: list[logging.LogRecord]) -> list[logging.LogRecord]: + """The records of statements the pass reports: those with a subject.""" + return [record for record in records if record.subject is not None] + + +def _assert_matches_report(records, report, backend: str) -> None: + logged = _pass_records(records) + assert [(r.subject, r.sql) for r in logged] == [ + (s.subject, s.sql) for s in report.statements + ] + for record in logged: + assert record.name == "ferro.sql" + assert record.levelno == logging.DEBUG + assert record.operation == "migrate" + assert record.params == () + assert record.dialect == backend + assert record.connection == "default" + assert isinstance(record.duration_ms, float) and record.duration_ms >= 0 + assert record.error is None + assert record.getMessage() == ( + f"{record.sql} params=() {record.duration_ms:.1f}ms" + ) + + +@pytest.mark.usefixtures("_fresh") +@pytest.mark.asyncio +async def test_create_tables_logs_one_record_per_reported_statement( + db_url, db_backend, statement_records +): + _declare_author(bio=False) + await ferro.connect(db_url) + + report = await ferro.create_tables() + + assert [s.subject for s in report.statements if s.role == "schema"] == ["author"] + _assert_matches_report(statement_records, report, db_backend) + for record in statement_records: + assert {a: getattr(record, a) for a in RECORD_ATTRIBUTES}.keys() == set( + RECORD_ATTRIBUTES + ) + + +@pytest.mark.usefixtures("_fresh") +@pytest.mark.asyncio +async def test_migrate_logs_the_alter_it_ran(db_url, db_backend, statement_records): + _declare_author(bio=False) + await ferro.connect(db_url) + await ferro.create_tables() + _rewind() + _declare_author(bio=True) + await ferro.connect(db_url) + statement_records.clear() + + report = await ferro.migrate() + + _assert_matches_report(statement_records, report, db_backend) + assert ("author", 'ALTER TABLE "author" ADD COLUMN "bio" varchar') in [ + (r.subject, r.sql) for r in statement_records + ] + + +@pytest.mark.usefixtures("_fresh") +@pytest.mark.asyncio +async def test_with_the_log_off_the_emitter_is_never_called(db_url, monkeypatch): + calls: list[dict] = [] + monkeypatch.setattr(ferro._sql_log, "emit", calls.append) + logger = logging.getLogger("ferro.sql") + level = logger.level + logger.setLevel(logging.WARNING) + try: + _declare_author(bio=False) + await ferro.connect(db_url) + await ferro.create_tables() + await ferro.migrate() + finally: + logger.setLevel(level) + + assert calls == [] + + +@pytest.mark.usefixtures("_fresh") +@pytest.mark.asyncio +async def test_with_the_log_on_the_emitter_is_the_one_ferro_calls( + db_url, monkeypatch, statement_records +): + calls: list[dict] = [] + emit = ferro._sql_log.emit + + def spy(record: dict) -> None: + calls.append(record) + emit(record) + + monkeypatch.setattr(ferro._sql_log, "emit", spy) + _declare_author(bio=False) + await ferro.connect(db_url) + await ferro.create_tables() + + assert calls and len(calls) == len(statement_records) + + +@pytest.mark.usefixtures("_fresh") +@pytest.mark.asyncio +async def test_caplog_captures_statement_records_without_setup(db_url, caplog): + caplog.set_level(logging.DEBUG) + _declare_author(bio=False) + await ferro.connect(db_url) + + report = await ferro.create_tables() + + sql = [r for r in caplog.records if r.name == "ferro.sql"] + assert [r.sql for r in sql if r.subject is not None] == [ + s.sql for s in report.statements + ] + assert any(r.name == "ferro" for r in caplog.records) + + +def test_the_ferro_logger_has_only_a_null_handler_and_propagates(): + logger = logging.getLogger("ferro") + assert [type(h) for h in logger.handlers] == [logging.NullHandler] + assert logger.propagate is True + + +def test_redacted_reads_as_three_stars(): + assert repr(ferro._sql_log.REDACTED) == "***" + assert str(ferro._sql_log.REDACTED) == "***" + + +def test_emit_substitutes_redacted_for_masked_parameters(statement_records): + ferro._sql_log.emit( + { + "sql": 'SELECT 1 WHERE "token" = ?', + "params": (None, 7), + "mask": (True, False), + "dialect": "sqlite", + "duration_ms": 0.25, + "operation": "query", + "subject": None, + "connection": "default", + "rows": None, + "error": None, + } + ) + + (record,) = statement_records + assert record.params == (ferro._sql_log.REDACTED, 7) + assert record.getMessage() == 'SELECT 1 WHERE "token" = ? params=(***, 7) 0.2ms' + + +# -- a run ---------------------------------------------------------------------------- + +AUTHOR = """ +class Author(Model): + __ferro_table__ = "slog_author" + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str +""" + +LOGS_A_LINE = """\ +from ferro.migrations import atomic, nothing_to_reverse + + +@atomic +async def up(ctx): + ctx.log.info("backfilled 3 rows") + + +@nothing_to_reverse("nothing was written") +def down(ctx): ... +""" + + +@pytest.fixture +def chain(project, pkg, db, clean_registry): + configure(project, pkg, db.backend) + write_models(project, pkg, AUTHOR) + new("create_author") + return project + + +async def _connected(db) -> None: + await ferro.connect(db.url) + + +@pytest.mark.usefixtures("isolated_imports") +@pytest.mark.asyncio +async def test_a_run_logs_each_step_statement_under_its_step_file( + chain, db, statement_records +): + sql_step(chain, "seed", "INSERT INTO \"slog_author\" (name) VALUES ('Ada');\n") + await _connected(db) + try: + h = harness() + await h.apply("0001") + await h.apply("0002") + finally: + ferro.reset_engine() + + (ddl_file,) = (migrations(chain) / "0001_create_author").glob( + f"*.up.{db.backend}.sql" + ) + ddl = [ + r + for r in statement_records + if r.subject == f"0001_create_author/{ddl_file.name}" + and "lock_timeout" not in r.sql + ] + assert ddl and all(r.sql in ddl_file.read_text() for r in ddl) + seed = [ + r.sql + for r in statement_records + if r.subject == "0002_seed/01_seed.up.sql" and "lock_timeout" not in r.sql + ] + assert seed == ["INSERT INTO \"slog_author\" (name) VALUES ('Ada')"] + for record in ddl: + assert record.operation == "migrate" + assert record.connection == "default" + assert record.dialect == db.backend + assert record.params == () + assert record.error is None + + +@pytest.mark.usefixtures("isolated_imports") +@pytest.mark.asyncio +async def test_a_statement_the_database_rejects_is_logged_with_its_error( + chain, db, statement_records +): + sql_step(chain, "broken", 'INSERT INTO "nowhere" VALUES (1);\n') + await _connected(db) + try: + h = harness() + await h.apply("0001") + with pytest.raises(Exception) as raised: + await h.apply("0002") + finally: + ferro.reset_engine() + + (failed,) = [ + r + for r in statement_records + if r.subject == "0002_broken/01_broken.up.sql" and r.error is not None + ] + assert failed.sql == 'INSERT INTO "nowhere" VALUES (1)' + assert "nowhere" in failed.error + assert failed.getMessage().endswith(f" failed: {failed.error}") + assert "nowhere" in str(raised.value) + + +@pytest.mark.usefixtures("isolated_imports") +def test_ferro_migrate_up_prints_a_data_steps_log_line(chain, pkg, db, capsys): + write_models(chain, pkg, AUTHOR + " bio: str | None = None\n") + new("add_bio", "--data-step", "Author") + (step,) = (migrations(chain) / "0002_add_bio").glob("*.py") + step.write_text(LOGS_A_LINE) + capsys.readouterr() + + from tests.test_migrate_new import run + + assert run("migrate", "up", "--url", db.url) == 0 + + assert "backfilled 3 rows" in capsys.readouterr().err + logger = logging.getLogger("ferro") + assert [type(h) for h in logger.handlers] == [logging.NullHandler] From ca92eca937111d0bff34223eb672c6e3fa9c2374 Mon Sep 17 00:00:00 2001 From: 0x54 Date: Wed, 21 Oct 2026 02:36:31 -0400 Subject: [PATCH 2/5] feat(log): every operation statement in the log, with secrets redacted (#765) (#769) Every FFI operation entry opens the statement context with its operation and connection: queries, mutations, bulk and many-to-many operations, raw SQL, transaction control, the session-settings batch and the catalog probe each leave one ferro.sql record per statement. Redaction is a secret-value set per operation: Python collects the values it unwraps from secret types (compile_query, the bind-payload helpers, raw), Rust adds the values bound to declared secret columns, and a bind equal to any of them is emitted as ***. Interfaces changed: count_filtered takes operation="count"|"exists" (exists() runs through it); close_session requires connection_name (the settings reset on close is logged under its connection). Closes #765 Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP --- src/ferro/_bind_payload.py | 35 +++ src/ferro/_core.pyi | 23 +- src/ferro/models.py | 26 +- src/ferro/query/builder.py | 13 +- src/ferro/query/wire.py | 69 ++++- src/ferro/raw.py | 41 ++- src/ferro/session.py | 3 +- src/operations.rs | 517 ++++++++++++++++++++++++++----- src/session_settings.rs | 12 +- src/sql_log.rs | 114 ++++++- tests/test_compiled_query.py | 53 ++++ tests/test_include.py | 2 +- tests/test_statement_log.py | 571 ++++++++++++++++++++++++++++++++++- 13 files changed, 1391 insertions(+), 88 deletions(-) diff --git a/src/ferro/_bind_payload.py b/src/ferro/_bind_payload.py index d2666113..488610b2 100644 --- a/src/ferro/_bind_payload.py +++ b/src/ferro/_bind_payload.py @@ -41,6 +41,41 @@ def unwrap_secret(value: Any) -> Any: return value +def secret_values_of(fields: Mapping[str, object]) -> tuple[object, ...]: + """Return what each `SecretStr` / `SecretBytes` among `fields`' values hides. + + The statement log masks a bound parameter equal to any of these, so a + secret written through this mapping never reaches a record. + + Args: + fields: Field or column names mapped to the values about to be bound. + + Returns: + The unwrapped value of every secret in `fields`, in order; empty when + there is none. + """ + return tuple( + unwrap_secret(value) + for value in fields.values() + if isinstance(value, (SecretStr, SecretBytes)) + ) + + +def secret_values(instance: Any) -> tuple[object, ...]: + """Return what each secret field of a model instance hides. + + Args: + instance: The model instance about to be saved. + + Returns: + The unwrapped value of every field holding a `SecretStr` or + `SecretBytes`, in field order; empty when there is none. + """ + return secret_values_of( + {name: getattr(instance, name, None) for name in type(instance).model_fields} + ) + + def _raw_bound_fields(instance: Any) -> dict[str, Any]: """Fields that bind raw rather than through the JSON dump, with that value. diff --git a/src/ferro/_core.pyi b/src/ferro/_core.pyi index 5fd18c38..a5bab693 100644 --- a/src/ferro/_core.pyi +++ b/src/ferro/_core.pyi @@ -650,11 +650,16 @@ async def fetch_filtered( route: RouteHandle, record_cls: type | None = None, hop_classes: dict[str, type] | None = None, + *, + secret_values: list[object] = ..., ) -> list[Any]: ... async def count_filtered( name: str, query_ir_json: str, route: RouteHandle, + *, + secret_values: list[object] = ..., + operation: Literal["count", "exists"] = "count", ) -> int: ... async def fetch_one( cls: object, @@ -666,16 +671,22 @@ async def save_record( data: dict[str, Any], route: RouteHandle, mode: str = "insert", + *, + secret_values: list[object] = ..., ) -> int | None: ... async def update_record( name: str, data: dict[str, Any], route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> int: ... async def save_bulk_records( name: str, rows: list[dict[str, Any]], route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> int: ... async def delete_record( name: str, @@ -686,11 +697,15 @@ async def delete_filtered( name: str, query_ir_json: str, route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> int: ... async def update_filtered( name: str, query_ir_json: str, route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> int: ... async def add_m2m_links( join_table: str, @@ -727,7 +742,7 @@ def open_session( settings: Optional[list[tuple[str, str]]] = None, declared: Optional[list[tuple[str, str]]] = None, ) -> tuple[str, str]: ... -async def close_session(session_id: str) -> None: ... +async def close_session(session_id: str, connection_name: str) -> None: ... async def set_session_config( session_id: str, connection_name: str, @@ -739,16 +754,22 @@ async def raw_execute( args: list[Any], route: RouteHandle, autocommit: bool = False, + *, + secret_values: list[object] = ..., ) -> int: ... async def raw_fetch_all( sql: str, args: list[Any], route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> list[dict[str, Any]]: ... async def raw_fetch_one( sql: str, args: list[Any], route: RouteHandle, + *, + secret_values: list[object] = ..., ) -> dict[str, Any] | None: ... def register_instance( name: str, diff --git a/src/ferro/models.py b/src/ferro/models.py index f21a2cd3..3f245b08 100644 --- a/src/ferro/models.py +++ b/src/ferro/models.py @@ -1,5 +1,6 @@ """Define the core ORM model base and transaction helpers for Ferro.""" +import logging from contextlib import asynccontextmanager from enum import Enum from typing import ( @@ -26,7 +27,9 @@ apply_save_only, normalize_save_columns, save_bind_payload, + secret_values, ) +from ._sql_log import LOGGER as _SQL_LOG from ._core import ( begin_transaction, commit_transaction, @@ -54,6 +57,18 @@ route_for_transaction, ) + +def _secrets_to_mask(instances: "list[Model]") -> list[object]: + """The secret field values of `instances` the statement log must mask. + + Collected only while `ferro.sql` is enabled for `DEBUG`: with the log off + no record is written, so there is nothing to mask. + """ + if not _SQL_LOG.isEnabledFor(logging.DEBUG): + return [] + return [value for instance in instances for value in secret_values(instance)] + + _FERRO_CONNECTION_ATTR = "__ferro_connection_name" _FERRO_PERSISTED_ATTR = "__ferro_persisted" @@ -459,6 +474,7 @@ async def save( "Use Query.update() for set-oriented or expression writes." ) route, identity_using = await _instance_transaction_route(self, using, session) + secrets = _secrets_to_mask([self]) new_id = None if on_conflict == "update": new_id = await save_record( @@ -466,6 +482,7 @@ async def save( save_bind_payload(self), route, mode="upsert", + secret_values=secrets, ) elif _is_persisted(self): pk_field_name = self.__class__.__ferro_pk__ @@ -484,6 +501,7 @@ async def save( self.__class__.__ferro_identity__, payload, route, + secret_values=secrets, ) if rows_affected == 0: raise ModelDoesNotExist(self.__class__, pk_val) @@ -493,6 +511,7 @@ async def save( save_bind_payload(self), route, mode="insert", + secret_values=secrets, ) pk_val = None @@ -804,7 +823,12 @@ async def bulk_create( return 0 data = [save_bind_payload(i) for i in instances] route = await _transaction_or_using(using, session) - return await save_bulk_records(cls.__ferro_identity__, data, route) + return await save_bulk_records( + cls.__ferro_identity__, + data, + route, + secret_values=_secrets_to_mask(list(instances)), + ) @classmethod async def get_or_create( diff --git a/src/ferro/query/builder.py b/src/ferro/query/builder.py index 8f1305c9..16dc2c09 100644 --- a/src/ferro/query/builder.py +++ b/src/ferro/query/builder.py @@ -12,6 +12,7 @@ Any, Callable, Generic, + Literal, NamedTuple, Never, NoReturn, @@ -1253,6 +1254,7 @@ async def all(self) -> list[T]: compiled.wire_json, route, hop_classes=compiled.hop_classes, + secret_values=list(compiled.secret_values), ) if self._before is not None: rows.reverse() @@ -1269,12 +1271,18 @@ async def count(self) -> int: >>> isinstance(total, int) True """ + return await self._count("count") + + async def _count(self, operation: Literal["count", "exists"]) -> int: + """Count the matching rows, naming the statement-log records `operation`.""" compiled = compile_query(self, "count") route = await self._transaction_or_using() return await count_filtered( model_identity(self.model_cls), compiled.wire_json, route, + secret_values=list(compiled.secret_values), + operation=operation, ) @overload @@ -1346,6 +1354,7 @@ async def update(self, *args: Any, **fields: Any) -> int: model_identity(self.model_cls), compiled.wire_json, route, + secret_values=list(compiled.secret_values), ) async def first(self) -> T | None: @@ -1387,6 +1396,7 @@ async def delete(self) -> int: model_identity(self.model_cls), compiled.wire_json, route, + secret_values=list(compiled.secret_values), ) async def exists(self) -> bool: @@ -1400,7 +1410,7 @@ async def exists(self) -> bool: >>> isinstance(found, bool) True """ - return await self.count() > 0 + return await self._count("exists") > 0 async def add(self, *instances: Any) -> None: """Add links to a many-to-many relationship @@ -1818,6 +1828,7 @@ async def all(self) -> Rows[Row]: # type: ignore[override] # ty: ignore[invali route, record_cls=Row, hop_classes=compiled.hop_classes, + secret_values=list(compiled.secret_values), ) if self._before is not None: records.reverse() diff --git a/src/ferro/query/wire.py b/src/ferro/query/wire.py index 56e819ed..d3466868 100644 --- a/src/ferro/query/wire.py +++ b/src/ferro/query/wire.py @@ -25,7 +25,14 @@ from dataclasses import dataclass, field from typing import TYPE_CHECKING, Any, Literal, Mapping -from .._bind_payload import canonicalize_wire_scalar, update_bind_payload +from pydantic import SecretBytes, SecretStr + +from .._bind_payload import ( + canonicalize_wire_scalar, + secret_values_of, + unwrap_secret, + update_bind_payload, +) from ..state import resolve_compile_connection_name from .nodes import ( BinaryValueExpr, @@ -927,8 +934,67 @@ class — an ``instances`` plan (#286) or a ``record`` plan with traversed """ payload: QueryIrPayload + """The compiled QueryIR payload.""" wire_json: str + """The payload serialized as the versioned wire envelope.""" hop_classes: dict[str, type] | None + """The hop model classes keyed by physical table, or `None` when the plan + decodes through no hop's class.""" + secret_values: tuple[object, ...] = () + """What each `SecretStr` / `SecretBytes` literal the query compiled with + hides, unwrapped, in the order the compile met them; empty when there is + none. It travels beside the payload, never inside it: the statement log + masks a bound parameter equal to any of these.""" + + +def _collect_secret_literals(value: Any, out: list[object]) -> None: + """Append what each secret in one literal hides, reaching into lists.""" + if isinstance(value, (SecretStr, SecretBytes)): + out.append(unwrap_secret(value)) + elif isinstance(value, (list, tuple, set, frozenset)): + for item in value: + _collect_secret_literals(item, out) + + +def _collect_node_secrets(node: QueryNode, out: list[object]) -> None: + """Append the secret literals of one predicate tree, depth first.""" + if node.child is not None: + _collect_node_secrets(node.child, out) + elif node.exists is not None: + for inner in node.exists.where: + _collect_node_secrets(inner, out) + elif node.is_compound: + if node.left is not None: + _collect_node_secrets(node.left, out) + if node.right is not None: + _collect_node_secrets(node.right, out) + else: + _collect_secret_literals(node.value, out) + + +def _secret_literals( + query: "Query[Any]", + verb: QueryVerb, + assignments: Mapping[str, Any] | None, + recipe: Mapping[str, Any] | None, +) -> tuple[object, ...]: + """What every secret-typed literal the compile unwraps hides. + + Read from the same values the payload compiles from (predicate literals, + the SET values of an update, a fetch's position bounds), so the set and + the wire cannot disagree about which literals were secrets. + """ + out: list[object] = [] + for node in query.where_clause: + _collect_node_secrets(node, out) + if verb == "update": + out.extend( + secret_values_of(recipe if recipe is not None else assignments or {}) + ) + if verb == "fetch": + for bound in (query._after, query._before): + _collect_secret_literals(bound or (), out) + return tuple(out) def _payload_hop_classes(payload: QueryIrPayload) -> dict[str, type] | None: @@ -1044,6 +1110,7 @@ def compile_query( payload=payload, wire_json=to_wire_json(payload), hop_classes=_payload_hop_classes(payload), + secret_values=_secret_literals(query, verb, assignments, recipe), ) diff --git a/src/ferro/raw.py b/src/ferro/raw.py index 1d514fc0..7f5f3e0c 100644 --- a/src/ferro/raw.py +++ b/src/ferro/raw.py @@ -25,13 +25,16 @@ import decimal import enum import json +import logging import uuid from typing import Any +from ._bind_payload import secret_values_of, unwrap_secret from ._core import RouteHandle from ._core import raw_execute as _raw_execute from ._core import raw_fetch_all as _raw_fetch_all from ._core import raw_fetch_one as _raw_fetch_one +from ._sql_log import LOGGER as _SQL_LOG from .state import resolve_operation_scope __all__ = ["execute", "fetch_all", "fetch_one", "Transaction"] @@ -39,6 +42,7 @@ def _marshal(val: Any) -> bool | int | float | str | bytes | None: """Convert a Python value into a primitive accepted by the FFI bind path.""" + val = unwrap_secret(val) if val is None: return None if isinstance(val, bool): @@ -60,10 +64,21 @@ def _marshal(val: Any) -> bool | int | float | str | bytes | None: raise TypeError( f"Cannot bind {type(val).__name__} to raw SQL parameter (value={val!r}). " f"Supported: str, int, float, bool, bytes, None, UUID, datetime, date, " - f"time, Decimal, Enum, dict, list." + f"time, Decimal, Enum, dict, list, SecretStr, SecretBytes." ) +def _secrets_to_mask(args: tuple[Any, ...]) -> list[object]: + """The secret arguments the statement log must mask, unwrapped. + + Collected only while `ferro.sql` is enabled for `DEBUG`: with the log off + no record is written, so there is nothing to mask. + """ + if not _SQL_LOG.isEnabledFor(logging.DEBUG): + return [] + return list(secret_values_of({str(index): arg for index, arg in enumerate(args)})) + + def _check_sql(sql: str) -> None: if not isinstance(sql, str) or not sql.strip(): raise ValueError("sql must be a non-empty statement") @@ -114,7 +129,9 @@ async def execute( _check_sql(sql) marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) - return await _raw_execute(sql, marshalled, route, autocommit) + return await _raw_execute( + sql, marshalled, route, autocommit, secret_values=_secrets_to_mask(args) + ) async def fetch_all( @@ -128,7 +145,9 @@ async def fetch_all( _check_sql(sql) marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) - return await _raw_fetch_all(sql, marshalled, route) + return await _raw_fetch_all( + sql, marshalled, route, secret_values=_secrets_to_mask(args) + ) async def fetch_one( @@ -141,7 +160,9 @@ async def fetch_one( _check_sql(sql) marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) - return await _raw_fetch_one(sql, marshalled, route) + return await _raw_fetch_one( + sql, marshalled, route, secret_values=_secrets_to_mask(args) + ) class Transaction: @@ -166,14 +187,20 @@ def __init__(self, route: RouteHandle) -> None: async def execute(self, sql: str, *args: Any) -> int: _check_sql(sql) marshalled = [_marshal(a) for a in args] - return await _raw_execute(sql, marshalled, self._route) + return await _raw_execute( + sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + ) async def fetch_all(self, sql: str, *args: Any) -> list[dict[str, Any]]: _check_sql(sql) marshalled = [_marshal(a) for a in args] - return await _raw_fetch_all(sql, marshalled, self._route) + return await _raw_fetch_all( + sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + ) async def fetch_one(self, sql: str, *args: Any) -> dict[str, Any] | None: _check_sql(sql) marshalled = [_marshal(a) for a in args] - return await _raw_fetch_one(sql, marshalled, self._route) + return await _raw_fetch_one( + sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + ) diff --git a/src/ferro/session.py b/src/ferro/session.py index 565b56ef..d174702f 100644 --- a/src/ferro/session.py +++ b/src/ferro/session.py @@ -183,7 +183,8 @@ async def close(self) -> None: # awaitable exists — when transactions are still open. So an # exception from this line leaves the handle exactly as it # was: still open, still usable. - releasing = _core_close_session(self.session_id) + assert self.connection_name is not None # resolved at __aenter__ + releasing = _core_close_session(self.session_id, self.connection_name) self.session_id = None try: diff --git a/src/operations.rs b/src/operations.rs index 731b4d9a..1584a94d 100644 --- a/src/operations.rs +++ b/src/operations.rs @@ -1382,6 +1382,250 @@ fn engine_bind_values_from_sea(values: &[SeaValue]) -> Vec { .collect() } +/// The statement-log context an operation entry opens (ADR-0057), or `None` +/// when `ferro.sql` is not enabled for `DEBUG`. Asked once, while the entry +/// holds the GIL; `secret_values` is called only when the log is on, so an +/// operation with the log off builds no secret-value set. +/// +/// # Errors +/// The `PyErr` from asking the logger, or from `secret_values`. +fn operation_log( + py: Python<'_>, + operation: &'static str, + connection: &str, + secret_values: F, +) -> PyResult> +where + F: FnOnce(Python<'_>) -> PyResult>, +{ + if !crate::sql_log::enabled(py)? { + return Ok(None); + } + let mut context = crate::sql_log::StatementContext::new(operation, connection); + context.secret_values = secret_values(py)?; + Ok(Some(context)) +} + +/// No secret values: an operation that binds none (a primary key, link ids, +/// transaction control). +fn no_secrets(_py: Python<'_>) -> PyResult> { + Ok(Vec::new()) +} + +/// The binds the secret values Python collected make, through the same +/// conversion a raw bind takes (a secret is a `str` or `bytes`). +fn secret_binds_from_py(values: &[Bound<'_, PyAny>]) -> PyResult> { + values.iter().map(python_to_engine_bind_value).collect() +} + +/// The model classes the Python registry holds, keyed by identity. +fn registered_model_classes(py: Python<'_>) -> PyResult> { + Ok(py + .import("ferro.registry")? + .getattr("REGISTRY")? + .call_method0("models")? + .cast_into::()?) +} + +/// The model class registered under `identity`. +/// +/// # Errors +/// `PyRuntimeError` when no model is registered under `identity`. +fn model_class_for<'py>(py: Python<'py>, identity: &str) -> PyResult> { + registered_model_classes(py)? + .get_item(identity)? + .ok_or_else(|| { + pyo3::exceptions::PyRuntimeError::new_err(format!( + "No model class is registered as '{identity}'" + )) + }) +} + +/// The model class whose table is `table`. +/// +/// # Errors +/// `PyRuntimeError` when no registered model owns the table. +fn model_class_for_table<'py>(py: Python<'py>, table: &str) -> PyResult> { + for (identity, cls) in registered_model_classes(py)?.iter() { + let identity = identity.extract::()?; + if crate::state::registered_model(&identity).is_ok_and(|model| model.table_name == table) { + return Ok(cls); + } + } + Err(pyo3::exceptions::PyRuntimeError::new_err(format!( + "No registered model owns table '{table}'" + ))) +} + +/// The secret columns of each table a query touches, read once per table +/// from its model class's converter registry. +struct SecretColumns<'py> { + py: Python<'py>, + by_table: HashMap>, +} + +impl<'py> SecretColumns<'py> { + fn new(py: Python<'py>, root_table: &str, root_cls: &Bound<'py, PyAny>) -> PyResult { + let mut by_table = HashMap::new(); + by_table.insert( + root_table.to_string(), + crate::sql_log::secret_columns_for(py, root_cls)?, + ); + Ok(Self { py, by_table }) + } + + fn contains(&mut self, table: &str, column: &str) -> PyResult { + if let Some(columns) = self.by_table.get(table) { + return Ok(columns.contains(column)); + } + let cls = model_class_for_table(self.py, table)?; + let columns = crate::sql_log::secret_columns_for(self.py, &cls)?; + let found = columns.contains(column); + self.by_table.insert(table.to_string(), columns); + Ok(found) + } +} + +/// The table a leaf's relation `path` reaches from `scope_table` through +/// `joins`: the path's last hop's table. +/// +/// # Errors +/// `PyValueError` when no join carries the path. +fn table_for_path( + scope_table: &str, + joins: &[ferro_schema_ir::QueryJoin], + path: &[String], +) -> PyResult { + let Some(last) = path.len().checked_sub(1) else { + return Ok(scope_table.to_string()); + }; + joins + .iter() + .find(|join| { + join.path.len() > last + && join + .path + .iter() + .zip(path) + .all(|(hop, name)| &hop.relation == name) + }) + .and_then(|join| join.path.get(last)) + .map(|hop| hop.to_table.clone()) + .ok_or_else(|| { + pyo3::exceptions::PyValueError::new_err(format!( + "relation path {path:?} has no matching join entry" + )) + }) +} + +fn collect_secret_leaf_binds( + node: &ferro_schema_ir::QueryNode, + scope_table: &str, + joins: &[ferro_schema_ir::QueryJoin], + secret: &mut SecretColumns<'_>, + out: &mut Vec, +) -> PyResult<()> { + use ferro_schema_ir::QueryNode; + match node { + QueryNode::Leaf { + column, + value, + path, + .. + } => { + let table = table_for_path(scope_table, joins, path)?; + if secret.contains(&table, column)? { + crate::sql_log::literal_secret_binds(&value.kind, &value.value, out); + } + } + QueryNode::Compound { left, right, .. } => { + collect_secret_leaf_binds(left, scope_table, joins, secret, out)?; + collect_secret_leaf_binds(right, scope_table, joins, secret, out)?; + } + QueryNode::Not { child } => { + collect_secret_leaf_binds(child, scope_table, joins, secret, out)?; + } + QueryNode::Exists { + hops, + where_clause, + joins: inner_joins, + } => { + if let Some(target) = hops.last() { + for inner in where_clause { + collect_secret_leaf_binds(inner, &target.to_table, inner_joins, secret, out)?; + } + } + } + } + Ok(()) +} + +/// The values a query binds to secret columns: every predicate literal +/// compared against a column whose field the model (or a traversed hop's +/// model) declares `SecretStr` / `SecretBytes`, and every literal `SET` of +/// one. Added to the operation's secret-value set, beside the secret-typed +/// literals Python collected. +/// +/// # Errors +/// The `PyErr` from resolving a hop's model class or reading its converter +/// registry; `PyValueError` for a relation path with no join entry. +fn plan_secret_values( + py: Python<'_>, + root_cls: &Bound<'_, PyAny>, + plan: &QueryPlan, +) -> PyResult> { + let identity = crate::state::model_identity(root_cls)?; + let root_table = crate::state::registered_model(&identity)? + .table_name + .clone(); + let mut secret = SecretColumns::new(py, &root_table, root_cls)?; + let mut out = Vec::new(); + for node in &plan.where_clause { + collect_secret_leaf_binds(node, &root_table, &plan.joins, &mut secret, &mut out)?; + } + for assignment in &plan.set_assignments { + if let QueryValueExpr::Literal { value } = &assignment.value + && secret.contains(&root_table, &assignment.column)? + { + crate::sql_log::literal_secret_binds(&value.kind, &value.value, &mut out); + } + } + Ok(out) +} + +/// The values save payloads bind to the secret columns of `identity`'s +/// model. +fn payload_secret_values( + py: Python<'_>, + identity: &str, + rows: &[Bound<'_, pyo3::types::PyDict>], +) -> PyResult> { + let cls = model_class_for(py, identity)?; + let columns = crate::sql_log::secret_columns_for(py, &cls)?; + let mut out = Vec::new(); + for row in rows { + for column in &columns { + if let Some(value) = row.get_item(column)? + && !value.is_none() + { + out.push(python_to_engine_bind_value(&value)?); + } + } + } + Ok(out) +} + +/// The secret-value set of an operation: what Python collected, plus what +/// the entry found bound to secret columns. +fn operation_secret_values( + python_collected: &[Bound<'_, PyAny>], + found: Vec, +) -> PyResult> { + let mut values = secret_binds_from_py(python_collected)?; + values.extend(found); + Ok(values) +} + /// One execution route for an operation: a transaction's dedicated /// connection, or the routed engine's pool (FF-G G2). /// @@ -1567,12 +1811,14 @@ async fn postgres_catalog_rows( ) -> PyResult> { engine.record_catalog_query(); let values = [EngineBindValue::String(table_name.to_string())]; - exec.fetch_all(sql, &values).await.map_err(|e| { - crate::errors::map_db_error( - &format!("Failed to inspect {} for '{}'", label, table_name), - e, - ) - }) + crate::sql_log::with_operation(crate::sql_log::CATALOG, exec.fetch_all(sql, &values)) + .await + .map_err(|e| { + crate::errors::map_db_error( + &format!("Failed to inspect {} for '{}'", label, table_name), + e, + ) + }) } macro_rules! sea_query_build_for_backend { @@ -1749,7 +1995,13 @@ pub fn begin_transaction( route: Py, immediate: bool, ) -> PyResult> { - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log( + py, + crate::sql_log::TRANSACTION, + &route.get().connection_name, + no_secrets, + )?; + let operation = async move { let r = route.get(); let tx_id = uuid::Uuid::new_v4().to_string(); if let Some(parent_tx_id) = r.tx_id.clone() { @@ -1815,7 +2067,24 @@ pub fn begin_transaction( } Ok(tx_id) - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) +} + +/// The statement-log context of ending transaction `tx_id`: its statements +/// are `transaction` statements on the connection it was opened on. An +/// unknown id opens none (the entry fails before sending anything). +fn transaction_log( + py: Python<'_>, + tx_id: &str, + session_id: Option<&str>, +) -> PyResult> { + if !crate::sql_log::enabled(py)? { + return Ok(None); + } + Ok(tx_get(session_id, tx_id)?.map(|tx| { + crate::sql_log::StatementContext::new(crate::sql_log::TRANSACTION, tx.connection_name) + })) } /// Commit a transaction or release a nested savepoint. @@ -1836,7 +2105,8 @@ pub fn commit_transaction( tx_id: String, session_id: Option, ) -> PyResult> { - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = transaction_log(py, &tx_id, session_id.as_deref())?; + let operation = async move { let tx_handle = tx_remove(session_id.as_deref(), &tx_id)? .ok_or_else(|| pyo3::exceptions::PyRuntimeError::new_err("Transaction not found"))?; @@ -1856,7 +2126,8 @@ pub fn commit_transaction( })?; Ok(()) - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Give up on a session's pinned connection when ending a transaction on it @@ -1916,7 +2187,8 @@ pub fn rollback_transaction( tx_id: String, session_id: Option, ) -> PyResult> { - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = transaction_log(py, &tx_id, session_id.as_deref())?; + let operation = async move { let tx_handle = tx_remove(session_id.as_deref(), &tx_id)? .ok_or_else(|| pyo3::exceptions::PyRuntimeError::new_err("Transaction not found"))?; @@ -1945,7 +2217,8 @@ pub fn rollback_transaction( // Re-acquire the GIL before accessing identity map (async context has no GIL). pyo3::Python::attach(|_py| identity_map_clear(session_id.as_deref()))?; Ok(()) - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Open a session that pins connection routing and isolates transaction/identity state. @@ -2006,6 +2279,8 @@ pub fn open_session( /// /// Args: /// session_id (str): Id returned by `open_session`. +/// connection_name (str): The connection the session is bound to, which +/// names the reset's records in the statement log. /// /// Returns: /// None @@ -2015,19 +2290,26 @@ pub fn open_session( /// unknown, or when the reset fails — in which case the session is closed /// regardless and its connection has been discarded rather than pooled. #[pyfunction] -pub fn close_session(py: Python<'_>, session_id: String) -> PyResult> { +#[pyo3(signature = (session_id, connection_name))] +pub fn close_session( + py: Python<'_>, + session_id: String, + connection_name: String, +) -> PyResult> { + let log = operation_log(py, crate::sql_log::SETTINGS, &connection_name, no_secrets)?; ensure_session_idle_for_close(&session_id)?; let session = unregister_session(&session_id).ok_or_else(|| { pyo3::exceptions::PyRuntimeError::new_err(format!("Session '{}' is not active", session_id)) })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let pin = session.pinned.lock().await.take(); match pin { Some(pin) => release_pinned_connection(pin).await, None => Ok(()), } - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Mutate a live session's effective settings (`Session.set_config`, #411). @@ -2117,8 +2399,9 @@ pub fn set_session_config( &connection_name, &[(key.clone(), value.clone())], )?; + let log = operation_log(py, crate::sql_log::SETTINGS, &connection_name, no_secrets)?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let session = session_state(&session_id)?; // Serializes this whole sequence — including the read below — against // any other `set_config` on this session (see the lost-update note @@ -2145,7 +2428,8 @@ pub fn set_session_config( deliver_changed_settings(&engine, &session, &new_effective).await?; Ok(new_effective) - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Fetches all records for a given model class. @@ -2170,8 +2454,9 @@ pub fn fetch_all<'py>( ) -> PyResult> { let name = crate::state::model_identity(&cls)?; let cls_py = cls.unbind(); + let log = operation_log(py, "fetch", &route.get().connection_name, no_secrets)?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (connection_name, engine, tx_conn, backend) = route_engine(r)?; @@ -2271,7 +2556,8 @@ pub fn fetch_all<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Fetches a single record by its primary key. @@ -2301,8 +2587,9 @@ pub fn fetch_one<'py>( // No identity-map short-circuit before the query (FF-D D1b): the map is // an identity/dedup structure, not a query cache — every fetch reads the // database and refreshes the cached instance in place. + let log = operation_log(py, "fetch", &route.get().connection_name, no_secrets)?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (connection_name, engine, tx_conn, backend) = route_engine(r)?; @@ -2410,7 +2697,8 @@ pub fn fetch_one<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Render the INSERT statement for `save_record`. @@ -2591,17 +2879,24 @@ fn build_update_by_pk_sql( /// Returns a `PyErr` if the engine is not initialized, the model is not /// registered, the mode is unknown, or a column value cannot be bound. #[pyfunction] -#[pyo3(signature = (name, data, route, mode="insert"))] +#[pyo3(signature = (name, data, route, mode="insert", *, secret_values=Vec::new()))] pub fn save_record<'py>( py: Python<'py>, name: String, data: Bound<'py, pyo3::types::PyDict>, route: Py, mode: &str, + secret_values: Vec>, ) -> PyResult> { let bind_inputs = bind_inputs_from_py(&data)?; // GIL held here, before the async move let mode = parse_save_mode(mode)?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "save", &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + payload_secret_values(py, &name, std::slice::from_ref(&data))?, + ) + })?; + let operation = async move { let r = route.get(); let (_connection_name, engine, tx_conn, backend) = route_engine(r)?; @@ -2666,7 +2961,8 @@ pub fn save_record<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// UPDATE one row by primary key: `UPDATE SET WHERE = ?`. @@ -2687,15 +2983,22 @@ pub fn save_record<'py>( /// is missing/null; `PyRuntimeError` on registry failures; typed /// `ferro.exceptions` subclasses on database errors. #[pyfunction] -#[pyo3(signature = (name, data, route))] +#[pyo3(signature = (name, data, route, *, secret_values=Vec::new()))] pub fn update_record<'py>( py: Python<'py>, name: String, data: Bound<'py, pyo3::types::PyDict>, route: Py, + secret_values: Vec>, ) -> PyResult> { let bind_inputs = bind_inputs_from_py(&data)?; // GIL held here, before the async move - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "save", &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + payload_secret_values(py, &name, std::slice::from_ref(&data))?, + ) + })?; + let operation = async move { let r = route.get(); let (_connection_name, engine, tx_conn, backend) = route_engine(r)?; @@ -2763,7 +3066,8 @@ pub fn update_record<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Persist multiple model instances in as few batch `INSERT`s as the @@ -2787,18 +3091,22 @@ pub fn update_record<'py>( /// # Errors /// `PyRuntimeError` on registry/execute failures; `PyTypeError` for unbindable values. #[pyfunction] -#[pyo3(signature = (name, rows, route))] +#[pyo3(signature = (name, rows, route, *, secret_values=Vec::new()))] pub fn save_bulk_records<'py>( py: Python<'py>, name: String, rows: Vec>, route: Py, + secret_values: Vec>, ) -> PyResult> { let record_inputs: Vec> = rows .iter() .map(bind_inputs_from_py) .collect::>()?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "bulk_create", &route.get().connection_name, |py| { + operation_secret_values(&secret_values, payload_secret_values(py, &name, &rows)?) + })?; + let operation = async move { let r = route.get(); let (_connection_name, engine, tx_conn, backend) = route_engine(r)?; @@ -2923,7 +3231,8 @@ pub fn save_bulk_records<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Rows per INSERT statement so `rows × columns` never exceeds the backend's @@ -2989,7 +3298,9 @@ mod bulk_chunking_tests { /// list[PyAny]: Hydrated model instances (populated when included), or /// projected records. #[pyfunction] -#[pyo3(signature = (cls, query_ir_json, route, record_cls=None, hop_classes=None))] +#[pyo3(signature = ( + cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() +))] pub fn fetch_filtered<'py>( py: Python<'py>, cls: Bound<'py, PyAny>, @@ -2997,6 +3308,7 @@ pub fn fetch_filtered<'py>( route: Py, record_cls: Option>, hop_classes: Option>, + secret_values: Vec>, ) -> PyResult> { let name = crate::state::model_identity(&cls)?; let cls_py = cls.unbind(); @@ -3064,8 +3376,14 @@ pub fn fetch_filtered<'py>( )); } }; + let log = operation_log(py, "fetch", &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + plan_secret_values(py, cls_py.bind(py), &plan)?, + ) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (connection_name, engine, tx_conn, backend) = route_engine(r)?; let session_id = r.session_id.clone(); @@ -3231,7 +3549,7 @@ pub fn fetch_filtered<'py>( let hop_classes_py = hop_classes_py.ok_or_else(|| { pyo3::exceptions::PyRuntimeError::new_err( "Query plan includes related rows but carries no hop classes to \ - hydrate them with", + hydrate them with", ) })?; @@ -3255,7 +3573,7 @@ pub fn fetch_filtered<'py>( hop_classes.get_item(hop.table.as_str())?.ok_or_else(|| { pyo3::exceptions::PyValueError::new_err(format!( "fetch_filtered(): hop_classes has no model class \ - for included table {:?}.", + for included table {:?}.", hop.table )) })?; @@ -3442,7 +3760,8 @@ pub fn fetch_filtered<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Return the number of rows matching a filtered query. @@ -3453,28 +3772,50 @@ pub fn fetch_filtered<'py>( /// tx_id (str | None): Optional active transaction. /// using (str | None): Connection override. /// session_id (str | None): Session-scoped routing when set. +/// secret_values (list[object]): The secret-typed literals the query +/// compiled with, masked in the statement log. +/// operation (str): `"count"`, or `"exists"` when the count answers +/// `exists()`; names the statement-log records. /// /// Returns: /// int: Row count. /// /// # Errors -/// `PyRuntimeError` on registry, planning, or SQL failures. +/// `PyRuntimeError` on registry, planning, or SQL failures; `PyValueError` +/// for an unknown `operation`. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route))] -pub fn count_filtered( - py: Python<'_>, +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new(), operation="count"))] +pub fn count_filtered<'py>( + py: Python<'py>, name: String, query_ir_json: String, route: Py, -) -> PyResult> { + secret_values: Vec>, + operation: &str, +) -> PyResult> { + let operation: &'static str = match operation { + "count" => "count", + "exists" => "exists", + other => { + return Err(pyo3::exceptions::PyValueError::new_err(format!( + "count_filtered operation must be 'count' or 'exists', got {other:?}" + ))); + } + }; let mut plan = query_plan_from_ir_json(&query_ir_json)?; validate_paging_shape(&plan, "count")?; validate_set_shape(&plan, "count")?; // count() is unaffected by projection (PRD #277 verb table): the Python // builder always emits root_instances on count payloads, projected or not. reject_unsupported_materialization(&plan, "count_filtered")?; + let log = operation_log(py, operation, &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + ) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; @@ -3566,7 +3907,8 @@ pub fn count_filtered( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Register a live Python instance in the identity map for deduplication. @@ -3637,7 +3979,8 @@ pub fn delete_record( pk_val: String, route: Py, ) -> PyResult> { - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "delete", &route.get().connection_name, no_secrets)?; + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; @@ -3690,7 +4033,8 @@ pub fn delete_record( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Delete rows matching a filtered query. @@ -3708,20 +4052,27 @@ pub fn delete_record( /// # Errors /// `PyRuntimeError` on planning or execute failure. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route))] -pub fn delete_filtered( - py: Python<'_>, +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +pub fn delete_filtered<'py>( + py: Python<'py>, name: String, query_ir_json: String, route: Py, -) -> PyResult> { + secret_values: Vec>, +) -> PyResult> { let mut plan = query_plan_from_ir_json(&query_ir_json)?; validate_set_shape(&plan, "delete")?; validate_paging_shape(&plan, "delete")?; reject_traversal_on_mutation(&plan, "delete")?; reject_unsupported_materialization(&plan, "delete")?; + let log = operation_log(py, "delete", &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + ) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; let session_id = r.session_id.clone(); @@ -3778,7 +4129,8 @@ pub fn delete_filtered( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Update rows matching a filtered query using its canonical QueryIR SET section. @@ -3796,12 +4148,13 @@ pub fn delete_filtered( /// # Errors /// `PyTypeError` for unbindable column values; `PyRuntimeError` on execute failure. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] pub fn update_filtered<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, + secret_values: Vec>, ) -> PyResult> { let mut plan = query_plan_from_ir_json(&query_ir_json)?; validate_set_shape(&plan, "update")?; @@ -3814,7 +4167,13 @@ pub fn update_filtered<'py>( validate_paging_shape(&plan, "update")?; reject_traversal_on_mutation(&plan, "update")?; reject_unsupported_materialization(&plan, "update")?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "update", &route.get().connection_name, |py| { + operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + ) + })?; + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; let session_id = r.session_id.clone(); @@ -3893,7 +4252,8 @@ pub fn update_filtered<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Insert many-to-many association rows into a join table. @@ -3931,7 +4291,8 @@ pub fn add_m2m_links<'py>( .map(|id| python_to_sea_value(id)) .collect::>>()?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "m2m_add", &route.get().connection_name, no_secrets)?; + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; @@ -3984,7 +4345,8 @@ pub fn add_m2m_links<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Delete specific many-to-many association rows from a join table. @@ -4022,7 +4384,8 @@ pub fn remove_m2m_links<'py>( .map(|id| python_to_sea_value(id)) .collect::>>()?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let log = operation_log(py, "m2m_remove", &route.get().connection_name, no_secrets)?; + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; @@ -4074,7 +4437,8 @@ pub fn remove_m2m_links<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Delete all many-to-many links for a source row from a join table. @@ -4102,8 +4466,9 @@ pub fn clear_m2m_links<'py>( route: Py, ) -> PyResult> { let s_id = python_to_sea_value(source_id)?; + let log = operation_log(py, "m2m_clear", &route.get().connection_name, no_secrets)?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let r = route.get(); let (_, engine, tx_conn, backend) = route_engine(r)?; @@ -4140,7 +4505,8 @@ pub fn clear_m2m_links<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Convert a Python value into a SeaQuery `Value` for M2M source / target IDs. @@ -4588,13 +4954,14 @@ fn get_raw_tx_conn( /// not a supported primitive (the Python `_marshal` wrapper guarantees this /// never trips in normal use). #[pyfunction] -#[pyo3(signature = (sql, args, route, autocommit=false))] +#[pyo3(signature = (sql, args, route, autocommit=false, *, secret_values=Vec::new()))] pub fn raw_execute<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, autocommit: bool, + secret_values: Vec>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -4613,8 +4980,11 @@ pub fn raw_execute<'py>( ) }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; + let log = operation_log(py, "raw", &route_connection_name, |_| { + secret_binds_from_py(&secret_values) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let engine = engine_for_connection(Some(route_connection_name))?; // `autocommit=True` is the caller telling us this statement cannot run // inside a transaction at all (`CREATE INDEX CONCURRENTLY`, `VACUUM`), @@ -4645,7 +5015,8 @@ pub fn raw_execute<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Run a raw SQL query and return all rows as a list of dicts. @@ -4654,12 +5025,13 @@ pub fn raw_execute<'py>( /// UUID/datetime/JSON columns come back as strings — Ferro does not decode them /// for raw SQL. If you want typed rows, use the ORM. #[pyfunction] -#[pyo3(signature = (sql, args, route))] +#[pyo3(signature = (sql, args, route, *, secret_values=Vec::new()))] pub fn raw_fetch_all<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, + secret_values: Vec>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -4674,8 +5046,11 @@ pub fn raw_fetch_all<'py>( ) }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; + let log = operation_log(py, "raw", &route_connection_name, |_| { + secret_binds_from_py(&secret_values) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let engine = engine_for_connection(Some(route_connection_name))?; let scope = OperationScope::open( &engine, @@ -4704,7 +5079,8 @@ pub fn raw_fetch_all<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Run a raw SQL query and return the first row as a dict, or `None`. @@ -4722,12 +5098,13 @@ pub fn raw_fetch_all<'py>( /// Values are wire-close primitives (`str | int | float | bool | bytes | None`). /// UUID/datetime/JSON columns come back as strings — use the ORM for typed hydration. #[pyfunction] -#[pyo3(signature = (sql, args, route))] +#[pyo3(signature = (sql, args, route, *, secret_values=Vec::new()))] pub fn raw_fetch_one<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, + secret_values: Vec>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -4742,8 +5119,11 @@ pub fn raw_fetch_one<'py>( ) }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; + let log = operation_log(py, "raw", &route_connection_name, |_| { + secret_binds_from_py(&secret_values) + })?; - pyo3_async_runtimes::tokio::future_into_py(py, async move { + let operation = async move { let engine = engine_for_connection(Some(route_connection_name))?; let scope = OperationScope::open( &engine, @@ -4769,7 +5149,8 @@ pub fn raw_fetch_one<'py>( .await; scope.finish(outcome).await - }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } /// Lifetime catalog-introspection query count for a connection's engine. diff --git a/src/session_settings.rs b/src/session_settings.rs index d74ecd5c..d3cc640a 100644 --- a/src/session_settings.rs +++ b/src/session_settings.rs @@ -267,7 +267,11 @@ pub async fn apply_settings_batch( let Some((sql, binds)) = render_set_config_batch(settings, is_local) else { return Ok(()); }; - conn.execute_sql_with_binds(&sql, &binds).await?; + crate::sql_log::with_operation( + crate::sql_log::SETTINGS, + conn.execute_sql_with_binds(&sql, &binds), + ) + .await?; Ok(()) } @@ -1036,7 +1040,11 @@ pub async fn release_pinned_connection(pin: Arc) -> PyResult<( let conn = guard .live() .map_err(|e| crate::errors::map_db_error("Failed to reset session settings", e))?; - match conn.execute_sql_with_binds(&sql, &binds).await { + let reset = crate::sql_log::with_operation( + crate::sql_log::SETTINGS, + conn.execute_sql_with_binds(&sql, &binds), + ); + match reset.await { // Taken out of the slot deliberately: dropping it *after* the // guard is what returns it to the pool, clean. Ok(_) => Ok(guard.release()), diff --git a/src/sql_log.rs b/src/sql_log.rs index cd58affe..c38f41da 100644 --- a/src/sql_log.rs +++ b/src/sql_log.rs @@ -24,6 +24,7 @@ use ferro_ddl_lowering::Dialect; use pyo3::prelude::*; use pyo3::sync::PyOnceLock; use pyo3::types::{PyBytes, PyDict, PyTuple}; +use std::collections::HashSet; use std::future::Future; use std::sync::{Arc, Mutex}; use std::time::Instant; @@ -35,6 +36,18 @@ const DEBUG: i32 = 10; /// sends. pub const MIGRATE: &str = "migrate"; +/// The `operation` of a session's `SET LOCAL` / `set_config` batch, inside +/// whichever operation's transaction it scopes. +pub const SETTINGS: &str = "settings"; + +/// The `operation` of the Postgres catalog probe an operation runs the first +/// time it touches a table in a schema epoch. +pub const CATALOG: &str = "catalog"; + +/// The `operation` of a `transaction()` block's own statements: `BEGIN`, +/// `SAVEPOINT`, `RELEASE`, `ROLLBACK TO`, `COMMIT`, `ROLLBACK`. +pub const TRANSACTION: &str = "transaction"; + static LOGGER: PyOnceLock> = PyOnceLock::new(); static EMITTER_MODULE: PyOnceLock> = PyOnceLock::new(); static UUID_CLASS: PyOnceLock> = PyOnceLock::new(); @@ -61,7 +74,9 @@ pub fn enabled(py: Python<'_>) -> PyResult { #[derive(Clone, Debug)] pub struct StatementContext { /// What sent the statements: `"migrate"` for the reconciliation pass and - /// a run. + /// a run; the operation's name (`"fetch"`, `"save"`, `"raw"`, ...) for + /// an operation entry; `"transaction"`, `"settings"` or `"catalog"` for + /// what an operation sends on another's behalf (see [`with_operation`]). pub operation: &'static str, /// The connection's name (`"default"` unless named). pub connection: String, @@ -171,6 +186,63 @@ pub async fn with_subject(subject: &str, fut: F) -> F::Output { } } +/// Run `fut` with the open scope's operation set to `operation`: the +/// statements an operation sends on another's behalf (its session settings +/// batch, its catalog probe). Outside a scope it is `fut` itself. +pub async fn with_operation(operation: &'static str, fut: F) -> F::Output { + match current() { + Some(active) => { + let child = Active { + context: StatementContext { + operation, + ..active.context.clone() + }, + failure: Arc::clone(&active.failure), + }; + ACTIVE.scope(Some(Arc::new(child)), fut).await + } + None => fut.await, + } +} + +/// The columns of `cls` whose field is a `SecretStr` / `SecretBytes`: the +/// fields its hydration-converter registry records with kind `"secret"`. +/// +/// # Errors +/// The `PyErr` from reading a malformed converter registry. +pub fn secret_columns_for(py: Python<'_>, cls: &Bound<'_, PyAny>) -> PyResult> { + Ok(crate::hydration::field_converters_for(py, cls)? + .into_iter() + .filter(|(_, converter)| converter.kind == "secret") + .map(|(field, _)| field) + .collect()) +} + +/// Add to `out` the binds a query literal's wire value makes: a string binds +/// as text, a `bytes` literal (a list of byte values) as bytes, and a list +/// (`IN`) as each of its items. Only the shapes a secret column can hold are +/// collected; a number or a boolean is never a secret column's value. +pub fn literal_secret_binds(kind: &str, value: &serde_json::Value, out: &mut Vec) { + match value { + serde_json::Value::String(text) => out.push(EngineBindValue::String(text.clone())), + serde_json::Value::Array(items) if kind == "bytes" => { + let bytes: Option> = items + .iter() + .map(|item| item.as_u64().and_then(|byte| u8::try_from(byte).ok())) + .collect(); + if let Some(bytes) = bytes { + out.push(EngineBindValue::Bytes(bytes)); + } + } + serde_json::Value::Array(items) => { + for item in items { + literal_secret_binds("", item, out); + } + } + _ => {} + } +} + /// Write one finished statement to the statement log: `sql` with `binds`, /// on `dialect`, sent at `started`, with what it returned (rows affected, /// `None` for a fetch, or the database's error). A no-op outside a scope. @@ -328,6 +400,46 @@ mod tests { assert_eq!(connection.as_deref(), Some("default")); } + #[tokio::test] + async fn with_operation_renames_the_statements_inside_it_and_no_others() { + let seen = scope(Some(StatementContext::new("save", "default")), async { + let inside = + with_operation(SETTINGS, async { current().map(|a| a.context.operation) }).await; + let after = current().map(|a| a.context.operation); + Ok::<_, PyErr>((inside, after)) + }) + .await; + let (inside, after) = match seen { + Ok(seen) => seen, + Err(err) => panic!("scope failed: {err}"), + }; + assert_eq!(inside, Some("settings")); + assert_eq!(after, Some("save")); + } + + #[tokio::test] + async fn with_operation_outside_a_scope_opens_none() { + assert!(with_operation(CATALOG, async { current().is_none() }).await); + } + + #[test] + fn literal_secret_binds_reads_strings_bytes_and_lists() { + let mut out = Vec::new(); + literal_secret_binds("string", &serde_json::json!("hunter2"), &mut out); + literal_secret_binds("bytes", &serde_json::json!([0, 255]), &mut out); + literal_secret_binds("list", &serde_json::json!(["a", "b"]), &mut out); + literal_secret_binds("int", &serde_json::json!(7), &mut out); + assert_eq!( + out, + vec![ + EngineBindValue::String("hunter2".into()), + EngineBindValue::Bytes(vec![0, 255]), + EngineBindValue::String("a".into()), + EngineBindValue::String("b".into()), + ] + ); + } + #[tokio::test] async fn with_subject_outside_a_scope_opens_none() { let inside = with_subject("author", async { current().is_none() }).await; diff --git a/tests/test_compiled_query.py b/tests/test_compiled_query.py index 2affa2e9..1e710b9c 100644 --- a/tests/test_compiled_query.py +++ b/tests/test_compiled_query.py @@ -15,6 +15,8 @@ class — an ``instances`` plan (#286) or a ``record`` plan with traversed import json from typing import Annotated +from pydantic import SecretStr + from ferro import BackRef, Model, Relation from ferro.base import FerroField, ForeignKey from ferro.query.builder import Query @@ -79,3 +81,54 @@ def test_hop_classes_cover_traversed_projection_paths(): def test_mutation_verbs_compile_with_no_hop_classes(): compiled = compile_query(Query(CQTransaction), "delete") assert compiled.hop_classes is None + + +# -- secret_values: the secret-typed literals the compile unwrapped ------------- + + +def test_secret_values_is_empty_without_a_secret_literal(): + compiled = compile_query( + Query(CQAccount).where(lambda account: account.label == "hunter2"), "fetch" + ) + assert compiled.secret_values == () + + +def test_secret_values_carries_each_unwrapped_secret_literal_and_the_wire_is_unchanged(): + plain = compile_query( + Query(CQAccount).where(lambda account: account.label == "hunter2"), "fetch" + ) + secret = compile_query( + Query(CQAccount).where(lambda account: account.label == SecretStr("hunter2")), + "fetch", + ) + assert secret.secret_values == ("hunter2",) + assert secret.wire_json == plain.wire_json + + +def test_secret_values_reach_into_membership_lists_and_negations(): + compiled = compile_query( + Query(CQAccount).where( + lambda account: ( + ~account.label.in_([SecretStr("a"), "b"]) + | (account.label == SecretStr("c")) + ) + ), + "count", + ) + assert compiled.secret_values == ("a", "c") + + +def test_secret_values_carry_update_assignments(): + secret = compile_query( + Query(CQAccount).where(lambda account: account.id == 1), + "update", + assignments={"label": SecretStr("hunter2")}, + ) + plain = compile_query( + Query(CQAccount).where(lambda account: account.id == 1), + "update", + assignments={"label": "hunter2"}, + ) + assert secret.secret_values == ("hunter2",) + assert plain.secret_values == () + assert secret.wire_json == plain.wire_json diff --git a/tests/test_include.py b/tests/test_include.py index 3658dc35..b56dbc55 100644 --- a/tests/test_include.py +++ b/tests/test_include.py @@ -455,7 +455,7 @@ async def test_count_payload_stays_root_instances_under_include(db_url, monkeypa root_instances and no include joins — pinned on the wire.""" captured = {} - async def _capture(name, query_ir_json, route): + async def _capture(name, query_ir_json, route, **_statement_log): captured["envelope"] = json.loads(query_ir_json) return 0 diff --git a/tests/test_statement_log.py b/tests/test_statement_log.py index d8eea4c7..b07e414a 100644 --- a/tests/test_statement_log.py +++ b/tests/test_statement_log.py @@ -15,17 +15,26 @@ collected and the emitter is never called. """ -from __future__ import annotations - import logging from typing import Annotated import pytest +from pydantic import SecretBytes, SecretStr import ferro import ferro._sql_log -from ferro import Model -from ferro.base import FerroField +from ferro import ( + BackRef, + ManyToMany, + Model, + Relation, + engines, + raw, + transaction, +) +from ferro._sql_log import REDACTED +from ferro.base import FerroField, ForeignKey +from ferro.exceptions import IntegrityError from ferro.migrations.testing import harness from tests.test_migrate_new import ( # noqa: F401 - fixtures pkg, @@ -349,3 +358,557 @@ def test_ferro_migrate_up_prints_a_data_steps_log_line(chain, pkg, db, capsys): assert "backfilled 3 rows" in capsys.readouterr().err logger = logging.getLogger("ferro") assert [type(h) for h in logger.handlers] == [logging.NullHandler] + + +# -- operations ----------------------------------------------------------------------- +# +# Every statement an operation sends is one record, named by its operation, and +# a secret value never reaches a record. + + +class SlogAccount(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + email: Annotated[str, FerroField(unique=True)] + token: SecretStr + key: SecretBytes | None = None + notes: Relation[list["SlogNote"]] = BackRef() + tags: Relation[list["SlogTag"]] = ManyToMany(related_name="accounts") + + +class SlogNote(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + label: str + account: Annotated[SlogAccount | None, ForeignKey(related_name="notes")] = None + + +class SlogTag(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str + accounts: Relation[list["SlogAccount"]] = BackRef() + + +class SlogItem(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + label: str + n: int + + +TENANT_KEY = "myapp.tenant_id" + + +def _ph(backend: str, n: int = 1) -> str: + return f"${n}" if backend == "postgres" else "?" + + +def _ada() -> SlogAccount: + return SlogAccount( + id=1, + email="ada@example.com", + token=SecretStr("sk_live_1"), + key=SecretBytes(b"k\x00\xff"), + ) + + +def _sent(records: list[logging.LogRecord]) -> list[logging.LogRecord]: + """The records of statements the operations themselves sent: everything + but the pass `connect` runs and the catalog probe, which runs only on a + table's first touch.""" + return [r for r in records if r.operation not in ("migrate", "catalog")] + + +def _assert_hidden(records: list[logging.LogRecord], *secrets: object) -> None: + for record in records: + message = record.getMessage() + for secret in secrets: + assert secret not in record.params + if isinstance(secret, str): + assert secret not in message + else: + assert repr(secret) not in message + + +def _assert_shared(record: logging.LogRecord, backend: str) -> None: + assert record.connection == "default" + assert record.dialect == backend + assert record.error is None + + +async def _connect(db_url: str) -> None: + await ferro.connect(db_url, auto_migrate=True) + + +@pytest.mark.asyncio +async def test_a_fetch_is_one_fetch_record(db_url, db_backend, statement_records): + await _connect(db_url) + async with engines.session(): + ada = _ada() + await ada.save() + await SlogNote(id=1, label="hello", account=ada).save() + statement_records.clear() + + notes = await ( + SlogNote.select() + .include(lambda note: note.account) + .where(lambda note: note.label == "hello") + .order_by(lambda note: note.id) + .all() + ) + + assert [note.id for note in notes] == [1] + (record,) = _sent(statement_records) + assert record.operation == "fetch" + assert record.sql.startswith("SELECT") + assert record.rows is None + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_count_and_exists_name_their_own_records( + db_url, db_backend, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + statement_records.clear() + + assert await SlogAccount.where(lambda account: account.id == 1).count() == 1 + assert await SlogAccount.where(lambda account: account.id == 1).exists() + + count, exists = _sent(statement_records) + assert (count.operation, exists.operation) == ("count", "exists") + for record in (count, exists): + assert "COUNT" in record.sql.upper() + assert record.rows is None + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_save_of_a_new_and_a_fetched_instance_is_save( + db_url, db_backend, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + fetched = await SlogAccount.get(1) + fetched.email = "ada@lovelace.dev" + await fetched.save() + + insert, get, update = _sent(statement_records) + assert (insert.operation, get.operation, update.operation) == ( + "save", + "fetch", + "save", + ) + assert insert.sql.startswith("INSERT INTO") + assert update.sql.startswith("UPDATE") + assert (insert.rows, update.rows) == (1, 1) + for record in (insert, get, update): + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_bulk_create_leaves_one_record_per_chunk( + db_url, db_backend, statement_records +): + await _connect(db_url) + rows = 33_000 # two binds a row: past one statement's bind limit on both + async with engines.session(): + inserted = await SlogItem.bulk_create( + [SlogItem(label="x", n=i) for i in range(rows)] + ) + + assert inserted == rows + inserts = [r for r in _sent(statement_records) if r.sql.startswith("INSERT")] + assert len(inserts) >= 2 + assert {r.operation for r in _sent(statement_records)} == {"bulk_create"} + assert sum(r.rows for r in inserts) == rows + + +@pytest.mark.asyncio +async def test_model_delete_is_delete(db_url, db_backend, statement_records): + await _connect(db_url) + async with engines.session(): + tag = SlogTag(id=1, name="a") + await tag.save() + statement_records.clear() + + await tag.delete() + + (record,) = _sent(statement_records) + assert (record.operation, record.rows) == ("delete", 1) + assert record.sql.startswith("DELETE") + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_query_update_and_delete_name_their_records( + db_url, db_backend, statement_records +): + await _connect(db_url) + async with engines.session(): + await SlogTag(id=1, name="a").save() + await SlogTag(id=2, name="b").save() + statement_records.clear() + + await SlogTag.where(lambda tag: tag.id <= 2).update(name="z") + await SlogTag.where(lambda tag: tag.id == 1).delete() + + update, delete = _sent(statement_records) + assert (update.operation, update.rows) == ("update", 2) + assert (delete.operation, delete.rows) == ("delete", 1) + for record in (update, delete): + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_many_to_many_add_remove_and_clear(db_url, db_backend, statement_records): + await _connect(db_url) + async with engines.session(): + account = _ada() + await account.save() + red = SlogTag(id=1, name="red") + blue = SlogTag(id=2, name="blue") + await red.save() + await blue.save() + statement_records.clear() + + await account.tags.add(red, blue) + added = _sent(statement_records) + statement_records.clear() + await account.tags.remove(red) + removed = _sent(statement_records) + statement_records.clear() + await account.tags.clear() + cleared = _sent(statement_records) + + assert added and {r.operation for r in added} == {"m2m_add"} + assert [r.operation for r in removed] == ["m2m_remove"] + assert [r.operation for r in cleared] == ["m2m_clear"] + assert removed[0].rows == 1 + for record in added + removed + cleared: + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_raw_statements_are_raw(db_url, db_backend, statement_records): + await _connect(db_url) + ph = _ph(db_backend) + async with engines.session(): + await SlogTag(id=1, name="a").save() + statement_records.clear() + + await raw.execute(f"UPDATE slogtag SET name = {ph} WHERE id = 1", "b") + await raw.fetch_all("SELECT name FROM slogtag") + await raw.fetch_one(f"SELECT name FROM slogtag WHERE id = {ph}", 1) + + execute, fetch_all, fetch_one = statement_records + assert {r.operation for r in statement_records} == {"raw"} + assert execute.params == ("b",) + assert (execute.rows, fetch_all.rows, fetch_one.rows) == (1, None, None) + for record in statement_records: + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +async def test_a_nested_transaction_logs_its_control_statements_in_order( + db_url, db_backend, statement_records +): + await _connect(db_url) + async with engines.session(): + await SlogTag(id=99, name="warm").save() + statement_records.clear() + + async with transaction(): + await SlogTag(id=1, name="outer").save() + async with transaction(): + await SlogTag(id=2, name="inner").save() + with pytest.raises(RuntimeError): + async with transaction(): + await SlogTag(id=3, name="undone").save() + raise RuntimeError("undo") + await SlogTag(id=4, name="after").save() + + seen = [(r.operation, r.sql.split()[0]) for r in _sent(statement_records)] + assert seen == [ + ("transaction", "BEGIN"), + ("save", "INSERT"), + ("transaction", "SAVEPOINT"), + ("save", "INSERT"), + ("transaction", "RELEASE"), + ("transaction", "SAVEPOINT"), + ("save", "INSERT"), + ("transaction", "ROLLBACK"), + ("transaction", "RELEASE"), + ("save", "INSERT"), + ("transaction", "COMMIT"), + ] + rollback_to = _sent(statement_records)[7] + assert rollback_to.sql.startswith("ROLLBACK TO SAVEPOINT") + for record in _sent(statement_records): + _assert_shared(record, db_backend) + + +@pytest.mark.asyncio +@pytest.mark.postgres_only +async def test_session_settings_are_settings_records_inside_the_operations_transaction( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await SlogTag(id=99, name="warm").save() + statement_records.clear() + + async with engines.session(settings={TENANT_KEY: "acme"}): + await SlogTag(id=1, name="scoped").save() + + seen = [(r.operation, r.sql.split()[0]) for r in _sent(statement_records)] + begin = seen.index(("save", "BEGIN")) + insert = seen.index(("save", "INSERT")) + commit = seen.index(("save", "COMMIT")) + settings = [i for i, (operation, _) in enumerate(seen) if operation == "settings"] + assert settings and all(begin < i < insert < commit for i in settings) + for index in settings: + record = _sent(statement_records)[index] + assert record.connection == "default" + assert record.dialect == "postgres" + + +@pytest.mark.asyncio +@pytest.mark.postgres_only +async def test_the_catalog_probe_is_logged_on_a_tables_first_touch_only( + db_url, statement_records +): + await _connect(db_url) + statement_records.clear() + async with engines.session(): + await SlogTag.where(lambda tag: tag.id == 1).all() + first = list(statement_records) + statement_records.clear() + await SlogTag.where(lambda tag: tag.id == 1).all() + second = list(statement_records) + + assert [r.operation for r in first] == ["catalog", "fetch"] + assert first[0].params == ("slogtag",) + assert first[0].connection == "default" + assert [r.operation for r in second] == ["fetch"] + + +# -- redaction ------------------------------------------------------------------------ + + +@pytest.mark.asyncio +async def test_secret_field_values_are_redacted_on_save_and_update( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + fetched = await SlogAccount.get(1) + fetched.token = SecretStr("sk_live_2") + await fetched.save() + + insert, _, update = _sent(statement_records) + assert [p for p in insert.params if p is REDACTED] == [REDACTED, REDACTED] + assert "ada@example.com" in insert.params + assert REDACTED in update.params + _assert_hidden(statement_records, "sk_live_1", "sk_live_2", b"k\x00\xff") + + +@pytest.mark.asyncio +async def test_secret_field_values_are_redacted_on_bulk_create( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await SlogAccount.bulk_create( + [ + SlogAccount(id=1, email="a@example.com", token=SecretStr("sk_a")), + SlogAccount(id=2, email="b@example.com", token=SecretStr("sk_b")), + ] + ) + + (insert,) = _sent(statement_records) + assert insert.operation == "bulk_create" + assert insert.params.count(REDACTED) == 2 + _assert_hidden(statement_records, "sk_a", "sk_b") + + +@pytest.mark.asyncio +async def test_a_plain_value_equal_to_a_secret_of_the_same_operation_is_masked( + db_url, statement_records +): + """The false positive runs in the safe direction: a value that happens to + equal a secret of the same operation is masked with it.""" + await _connect(db_url) + async with engines.session(): + await SlogAccount.bulk_create( + [ + SlogAccount( + id=1, email="a@example.com", token=SecretStr("b@example.com") + ), + SlogAccount(id=2, email="b@example.com", token=SecretStr("sk_b")), + ] + ) + + (insert,) = _sent(statement_records) + assert insert.params.count(REDACTED) == 3 + assert "a@example.com" in insert.params + _assert_hidden(statement_records, "b@example.com", "sk_b") + + +@pytest.mark.asyncio +async def test_query_update_redacts_secret_and_plain_values_for_a_secret_column( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + statement_records.clear() + + await SlogAccount.where(lambda account: account.id == 1).update( + token=SecretStr("sk_live_2") + ) + await SlogAccount.where(lambda account: account.id == 1).update( + token="sk_live_3" + ) + + first, second = _sent(statement_records) + assert first.params[0] is REDACTED + assert second.params[0] is REDACTED + assert 1 in second.params + _assert_hidden(statement_records, "sk_live_2", "sk_live_3") + + +@pytest.mark.asyncio +async def test_a_plain_literal_against_a_secret_column_is_redacted( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + statement_records.clear() + + found = await SlogAccount.where( + lambda account: account.token == "sk_live_1" + ).first() + count = await SlogNote.where( + lambda note: note.account.token == "sk_live_1" + ).count() + await SlogAccount.where(lambda account: account.token == "sk_live_1").delete() + + assert found is not None and count == 0 + for record in _sent(statement_records): + assert REDACTED in record.params + _assert_hidden(statement_records, "sk_live_1") + + +@pytest.mark.asyncio +async def test_a_secret_literal_against_a_plain_column_is_redacted( + db_url, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + statement_records.clear() + + found = await SlogAccount.where( + lambda account: account.email == SecretStr("ada@example.com") + ).first() + + assert found is not None + (record,) = _sent(statement_records) + assert record.params[0] is REDACTED + _assert_hidden(statement_records, "ada@example.com") + + +@pytest.mark.asyncio +async def test_a_secret_raw_argument_is_redacted(db_url, db_backend, statement_records): + await _connect(db_url) + ph = _ph(db_backend) + async with engines.session(): + await _ada().save() + statement_records.clear() + + await raw.execute( + f"UPDATE slogaccount SET token = {ph}", SecretStr("sk_live_2") + ) + row = await raw.fetch_one( + f"SELECT token FROM slogaccount WHERE token = {ph}", SecretStr("sk_live_2") + ) + await raw.fetch_all(f"SELECT id FROM slogaccount WHERE id = {ph}", 1) + + assert row == {"token": "sk_live_2"} + execute, fetch_one, fetch_all = statement_records + assert execute.params == (REDACTED,) + assert fetch_one.params == (REDACTED,) + assert fetch_all.params == (1,) + _assert_hidden(statement_records, "sk_live_2") + + +@pytest.mark.asyncio +async def test_with_the_log_off_no_operation_emits_or_collects_secrets( + db_url, db_backend, monkeypatch +): + import ferro.models + import ferro.raw + + calls: list[dict] = [] + collected: list[str] = [] + monkeypatch.setattr(ferro._sql_log, "emit", calls.append) + for module, name in ( + (ferro.models, "secret_values"), + (ferro.raw, "secret_values_of"), + ): + original = getattr(module, name) + + def counting(*args, _original=original, _name=name, **kwargs): + collected.append(_name) + return _original(*args, **kwargs) + + monkeypatch.setattr(module, name, counting) + logger = logging.getLogger("ferro.sql") + level = logger.level + logger.setLevel(logging.WARNING) + try: + await _connect(db_url) + async with engines.session(): + account = _ada() + await account.save() + account.token = SecretStr("sk_live_2") + await account.save() + await SlogAccount.bulk_create( + [SlogAccount(id=2, email="b@example.com", token=SecretStr("sk_b"))] + ) + await SlogAccount.where(lambda account: account.token == "sk_b").count() + await raw.execute( + f"UPDATE slogaccount SET token = {_ph(db_backend)}", + SecretStr("sk_live_3"), + ) + async with transaction(): + await SlogTag(id=1, name="a").save() + finally: + logger.setLevel(level) + + assert calls == [] + assert collected == [] + + +@pytest.mark.asyncio +async def test_a_failed_statement_is_logged_with_its_error_and_still_raises( + db_url, db_backend, statement_records +): + await _connect(db_url) + async with engines.session(): + await _ada().save() + statement_records.clear() + + with pytest.raises(IntegrityError): + await SlogAccount( + id=2, email="ada@example.com", token=SecretStr("sk_live_9") + ).save() + + (failed,) = _sent(statement_records) + assert failed.operation == "save" + assert failed.error is not None + assert failed.getMessage().endswith(f" failed: {failed.error}") + _assert_hidden(statement_records, "sk_live_9") From bcb9931e332c3a07a7f8894765acbff8a1adc9cc Mon Sep 17 00:00:00 2001 From: 0x54 Date: Wed, 21 Oct 2026 03:07:12 -0400 Subject: [PATCH 3/5] feat(query): .sql() on every Query terminal renders its statement (#766) (#770) Every Query terminal (all, first, count, exists, update, delete) carries a .sql() with the terminal's own signature that returns a RenderedSql (sql, params, dialect; str() is the SQL alone) instead of running. Each terminal's build step is one function shared by the executing and rendering FFI entries, so the rendered statement is the statement sent; rendering routes like the call, reads only the cached catalog, opens no transaction and writes nothing. params are masked with the operation's secret-value set. The parity pin (tests/test_rendered_statement.py) holds .sql() equal to the executed call's ferro.sql record for every terminal on both dialects, listed under I-1's enforcement. Interfaces changed: render_count(operation="count"|"exists") stands in for render_exists; terminal() returns TerminalMethod[S, P, R] binding to Terminal[P, R]; update keeps its two forms through _update_terminal (overloads on the call and on .sql). Closes #766 Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP --- AGENTS.md | 9 + docs/pages/api/queries.md | 6 + src/ferro/__init__.py | 4 +- src/ferro/_core.pyi | 36 + src/ferro/query/__init__.py | 3 + src/ferro/query/builder.py | 165 ++-- src/ferro/query/rendered.py | 232 ++++++ src/lib.rs | 4 + src/operations.rs | 1053 +++++++++++++++++-------- src/sql_log.rs | 64 +- tests/static_fixtures/bad_updates.py | 26 + tests/static_fixtures/good_updates.py | 26 + tests/test_query_typing.py | 43 + tests/test_rendered_statement.py | 369 +++++++++ tests/test_static_contracts.py | 41 + 15 files changed, 1694 insertions(+), 387 deletions(-) create mode 100644 src/ferro/query/rendered.py create mode 100644 tests/static_fixtures/bad_updates.py create mode 100644 tests/static_fixtures/good_updates.py create mode 100644 tests/test_rendered_statement.py diff --git a/AGENTS.md b/AGENTS.md index 007249fe..d87ca665 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -246,6 +246,15 @@ Phantom diffs are the canonical symptom that this invariant has been broken. pin the names (`test_index_name_matches_rust_runtime_*`). - `docs/solutions/patterns/cross-emitter-ddl-parity.md` documents the rule and the recipes below. +- On the query side, the rendered-statement parity pin in + `tests/test_rendered_statement.py` is the counterpart of the cross-emitter + pins: for every `Query` terminal (`all`, `first`, `count`, `exists`, + `update` in both forms, `delete`, through `Relation` and `ProjectedQuery` + too) on both dialects, with a secret column, `await query..sql()` + equals the `ferro.sql` record the executed call writes in `sql`, `params` + (the `REDACTED` sentinel included) and `dialect`. Both doors build the + statement through one `build_` function in `src/operations.rs`, + which the executing entry sends and its `render_` twin returns. ### Adding a new emitter diff --git a/docs/pages/api/queries.md b/docs/pages/api/queries.md index 1928584c..265673cd 100644 --- a/docs/pages/api/queries.md +++ b/docs/pages/api/queries.md @@ -37,6 +37,12 @@ An aggregate-only projection collapses to one record (read with `first()`). Mixi ::: ferro.query.builder.ProjectedQuery +::: ferro.RenderedSql + +::: ferro.REDACTED + +::: ferro.query.rendered.Terminal + ::: ferro.query.Row ::: ferro.query.Rows diff --git a/src/ferro/__init__.py b/src/ferro/__init__.py index 1e540208..21c1b644 100644 --- a/src/ferro/__init__.py +++ b/src/ferro/__init__.py @@ -50,7 +50,7 @@ _carrying_report, _run_pass, ) -from .query import Relation, Row, Rows, now +from .query import REDACTED, Relation, RenderedSql, Row, Rows, now from .raw import Transaction, execute, fetch_all, fetch_one from .rowsecurity import RowPolicy, RowSecurity from .session import Session, current_session, engines @@ -587,6 +587,8 @@ async def migrate( "Relation", "Row", "Rows", + "RenderedSql", + "REDACTED", "version", "create_tables", "migrate", diff --git a/src/ferro/_core.pyi b/src/ferro/_core.pyi index a5bab693..e1b2251b 100644 --- a/src/ferro/_core.pyi +++ b/src/ferro/_core.pyi @@ -707,6 +707,42 @@ async def update_filtered( *, secret_values: list[object] = ..., ) -> int: ... + +RenderedParts = tuple[str, tuple[object, ...], tuple[bool, ...], str] +"""A rendering entry's answer: the SQL, the parameters (`None` where +masked), the mask (`True` where the parameter is a secret) and the dialect.""" + +async def render_fetch( + cls: object, + query_ir_json: str, + route: RouteHandle, + record_cls: type | None = None, + hop_classes: dict[str, type] | None = None, + *, + secret_values: list[object] = ..., +) -> RenderedParts: ... +async def render_count( + name: str, + query_ir_json: str, + route: RouteHandle, + *, + secret_values: list[object] = ..., + operation: Literal["count", "exists"] = "count", +) -> RenderedParts: ... +async def render_update( + name: str, + query_ir_json: str, + route: RouteHandle, + *, + secret_values: list[object] = ..., +) -> RenderedParts: ... +async def render_delete( + name: str, + query_ir_json: str, + route: RouteHandle, + *, + secret_values: list[object] = ..., +) -> RenderedParts: ... async def add_m2m_links( join_table: str, source_col: str, diff --git a/src/ferro/query/__init__.py b/src/ferro/query/__init__.py index 355d97c7..56123300 100644 --- a/src/ferro/query/__init__.py +++ b/src/ferro/query/__init__.py @@ -12,9 +12,11 @@ ValueExpr, now, ) +from .rendered import REDACTED, RenderedSql from .rows import Row, Rows __all__ = [ + "REDACTED", "AggregateExpr", "FieldProxy", "Predicate", @@ -24,6 +26,7 @@ "QueryProxy", "Relation", "RelationProxy", + "RenderedSql", "Row", "RowSelector", "Rows", diff --git a/src/ferro/query/builder.py b/src/ferro/query/builder.py index 16dc2c09..6ac11d6f 100644 --- a/src/ferro/query/builder.py +++ b/src/ferro/query/builder.py @@ -7,15 +7,18 @@ """ import copy +from collections.abc import Awaitable from typing import ( TYPE_CHECKING, Any, Callable, + ClassVar, Generic, Literal, NamedTuple, Never, NoReturn, + Protocol, Self, Type, TypeVar, @@ -30,6 +33,10 @@ delete_filtered, fetch_filtered, remove_m2m_links, + render_count, + render_delete, + render_fetch, + render_update, update_filtered, ) from .nodes import ( @@ -44,6 +51,7 @@ ValueExpr, validate_query_column, ) +from .rendered import Terminal, send, terminal from .rows import Row, Rows from .wire import ( M2mContext, @@ -554,6 +562,48 @@ def _collect_dict_projection(result: dict[Any, Any]) -> tuple[_ProjectedField, . return tuple(fields) +if TYPE_CHECKING: + from .rendered import RenderedSql + + class _UpdateTerminal(Protocol[E]): + """`query.update` as a type checker reads it: a recipe or keyword + literals, never both, on the call and on `.sql()` alike.""" + + @overload + def __call__( + self, recipe: Callable[[QueryProxy[E]], dict[str, Any]], / + ) -> Awaitable[int]: ... + @overload + def __call__(self, /, **fields: Any) -> Awaitable[int]: ... + @overload + def sql( + self, recipe: Callable[[QueryProxy[E]], dict[str, Any]], / + ) -> Awaitable[RenderedSql]: ... + @overload + def sql(self, /, **fields: Any) -> Awaitable[RenderedSql]: ... + + class _UpdateMethod(Protocol): + """`Query.update` as a type checker reads it: reading it from a + `Query[E]` binds an `_UpdateTerminal[E]`.""" + + @overload + def __get__(self, query: None, owner: Any) -> "_UpdateMethod": ... + @overload + def __get__(self, query: "Query[E]", owner: Any) -> _UpdateTerminal[E]: ... + + +def _update_terminal(method: Callable[..., Awaitable[int]]) -> "_UpdateMethod": + """Make `Query.update` a [`terminal`][ferro.query.rendered.terminal] that + keeps its two forms apart statically. + + A terminal carries its method's one signature, and `update` has two + (a recipe, or keyword literals), so a type checker reads this terminal + through `_UpdateMethod`, whose call and `.sql()` are overloaded per form. + At runtime it is `terminal(method)`. + """ + return cast("_UpdateMethod", terminal(method)) + + class Query(Generic[T]): """Build and execute fluent ORM queries. @@ -1236,7 +1286,8 @@ def before(self, position: tuple[Any, ...] | T) -> Self: new._before = bound return new - async def all(self) -> list[T]: + @terminal + async def all(self: "Query[T]") -> list[T]: """Return all model instances that match the current query Returns: @@ -1249,7 +1300,7 @@ async def all(self) -> list[T]: """ compiled = compile_query(self, "fetch") route = await self._transaction_or_using() - rows = await fetch_filtered( + rows = await send(fetch_filtered, render_fetch)( self.model_cls, compiled.wire_json, route, @@ -1260,7 +1311,8 @@ async def all(self) -> list[T]: rows.reverse() return rows - async def count(self) -> int: + @terminal + async def count(self: "Query[T]") -> int: """Return the number of records that match the current query Returns: @@ -1277,7 +1329,7 @@ async def _count(self, operation: Literal["count", "exists"]) -> int: """Count the matching rows, naming the statement-log records `operation`.""" compiled = compile_query(self, "count") route = await self._transaction_or_using() - return await count_filtered( + return await send(count_filtered, render_count)( model_identity(self.model_cls), compiled.wire_json, route, @@ -1285,15 +1337,13 @@ async def _count(self, operation: Literal["count", "exists"]) -> int: operation=operation, ) - @overload + @_update_terminal async def update( - self, recipe: Callable[[QueryProxy[T]], dict[str, Any]], / - ) -> int: ... - - @overload - async def update(self, /, **fields: Any) -> int: ... - - async def update(self, *args: Any, **fields: Any) -> int: + self: "Query[T]", + recipe: Callable[[QueryProxy[T]], dict[str, Any]] | None = None, + /, + **fields: Any, + ) -> int: """Update all records matching the current query. Two doors, one SET wire: keyword literals (``update(name="x")``) or a @@ -1306,10 +1356,10 @@ async def update(self, *args: Any, **fields: Any) -> int: cannot be mixed. Args: - *args: Optional positional recipe callable receiving a + recipe: Optional positional recipe callable receiving a :class:`QueryProxy` and returning a non-empty ``dict`` of - root-column assignments. Nameless so a keyword ``recipe=`` - still SETs a column of that name. + root-column assignments. Positional-only, so a keyword + ``recipe=`` still SETs a column of that name. **fields: Field names and literal values to update. Returns: @@ -1335,9 +1385,6 @@ async def update(self, *args: Any, **fields: Any) -> int: ... } ... ) """ - if len(args) > 1: - raise TypeError("update() takes at most one positional recipe") - recipe = args[0] if args else None if recipe is not None and fields: raise TypeError( "update() accepts either a recipe callable or keyword " @@ -1350,14 +1397,15 @@ async def update(self, *args: Any, **fields: Any) -> int: else: compiled = compile_query(self, "update", assignments=fields) route = await self._transaction_or_using() - return await update_filtered( + return await send(update_filtered, render_update)( model_identity(self.model_cls), compiled.wire_json, route, secret_values=list(compiled.secret_values), ) - async def first(self) -> T | None: + @terminal + async def first(self: "Query[T]") -> T | None: """Return the first matching record, or None Returns: @@ -1371,7 +1419,8 @@ async def first(self) -> T | None: results = await self.limit(1).all() return results[0] if results else None - async def delete(self) -> int: + @terminal + async def delete(self: "Query[T]") -> int: """Delete all records matching the current query Returns: @@ -1392,14 +1441,15 @@ async def delete(self) -> int: """ compiled = compile_query(self, "delete") route = await self._transaction_or_using() - return await delete_filtered( + return await send(delete_filtered, render_delete)( model_identity(self.model_cls), compiled.wire_json, route, secret_values=list(compiled.secret_values), ) - async def exists(self) -> bool: + @terminal + async def exists(self: "Query[T]") -> bool: """Return whether at least one record matches the current query Returns: @@ -1724,7 +1774,8 @@ def _is_group_key_source(self, column: str, path: tuple[str, ...]) -> bool: for field in self._projection ) - def count(self): # type: ignore[override] + @terminal + def count(self: "ProjectedQuery[T]") -> Awaitable[int]: """Count matching rows — or raise on an aggregate projection (#295). On a plain projection ``count()`` stays projection-blind (#279's @@ -1745,7 +1796,8 @@ def count(self): # type: ignore[override] ) return super().count() - def exists(self): # type: ignore[override] + @terminal + def exists(self: "ProjectedQuery[T]") -> Awaitable[bool]: """Existence check — or raise on an aggregate projection (#295). Raises: @@ -1808,7 +1860,8 @@ def _read_projected_order_value(self, row: Row, entry: OrderByEntry) -> Any: ) return getattr(row, name) - async def all(self) -> Rows[Row]: # type: ignore[override] # ty: ignore[invalid-method-override] + @terminal + async def all(self: "ProjectedQuery[T]") -> Rows[Row]: # type: ignore[override] """Return the projected records for every matching row. Returns: @@ -1822,7 +1875,7 @@ async def all(self) -> Rows[Row]: # type: ignore[override] # ty: ignore[invali """ compiled = compile_query(self, "fetch") route = await self._transaction_or_using() - records = await fetch_filtered( + records = await send(fetch_filtered, render_fetch)( self.model_cls, compiled.wire_json, route, @@ -1834,7 +1887,8 @@ async def all(self) -> Rows[Row]: # type: ignore[override] # ty: ignore[invali records.reverse() return _ROWS_OF_ROW._wrap(records) - async def first(self) -> Row | None: # type: ignore[override] # ty: ignore[invalid-method-override] + @terminal + async def first(self: "ProjectedQuery[T]") -> Row | None: # type: ignore[override] """Return the first matching projected record, or None. Examples: @@ -1931,6 +1985,41 @@ def __repr__(self): ) +if TYPE_CHECKING: + + class _RelationAll: + """`Relation.all` as a type checker reads it: its rows are instances + of `E` whether the relation is written `Relation[list[E]]` or + `Relation[E]`.""" + + @overload + def __get__(self, query: None, owner: Any) -> "_RelationAll": ... + @overload + def __get__( + self, query: "Relation[list[E]]", owner: Any + ) -> Terminal[[], list[E]]: ... + @overload + def __get__( + self, query: "Relation[E]", owner: Any + ) -> Terminal[[], list[E]]: ... + def __get__(self, query: Any, owner: Any) -> Any: ... + + class _RelationFirst: + """`Relation.first` as a type checker reads it (see `_RelationAll`).""" + + @overload + def __get__(self, query: None, owner: Any) -> "_RelationFirst": ... + @overload + def __get__( + self, query: "Relation[list[E]]", owner: Any + ) -> Terminal[[], E | None]: ... + @overload + def __get__( + self, query: "Relation[E]", owner: Any + ) -> Terminal[[], E | None]: ... + def __get__(self, query: Any, owner: Any) -> Any: ... + + class Relation(Query[T]): """Represent lazy collection relationship queries with typing support @@ -1961,24 +2050,8 @@ class Relation(Query[T]): # Relation[T] as a query whose *rows* are model instances, regardless of whether # T is written as Model or list[Model] in the field annotation. if TYPE_CHECKING: - - @overload - async def all(self: "Relation[list[E]]") -> list[E]: ... - - @overload - async def all(self: "Relation[E]") -> list[E]: ... - - @overload - async def first(self: "Relation[list[E]]") -> E | None: ... - - @overload - async def first(self: "Relation[E]") -> E | None: ... - - async def all(self): # type: ignore[override] - return await super().all() - - async def first(self): # type: ignore[override] - return await super().first() + all: ClassVar["_RelationAll"] # type: ignore[assignment] + first: ClassVar["_RelationFirst"] # type: ignore[assignment] @classmethod def __get_pydantic_core_schema__(cls, _source_type, _handler): diff --git a/src/ferro/query/rendered.py b/src/ferro/query/rendered.py new file mode 100644 index 00000000..1c087d7f --- /dev/null +++ b/src/ferro/query/rendered.py @@ -0,0 +1,232 @@ +"""Rendered statements: what a query terminal would send, without sending it. + +A terminal (`all`, `first`, `count`, `exists`, `update`, `delete`) is an +`async def` method wrapped by [`terminal`][ferro.query.rendered.terminal]. +Calling it runs the method; its `.sql` attribute runs the same method in +render mode, where the one engine call that would send the statement is +swapped for its rendering twin. Both twins build the statement through the +same engine function, so `.sql()` returns exactly what the call sends. +""" + +from __future__ import annotations + +import functools +from collections.abc import Awaitable, Callable +from contextvars import ContextVar +from dataclasses import dataclass +from typing import ( + TYPE_CHECKING, + Any, + Concatenate, + Generic, + Literal, + ParamSpec, + TypeVar, + overload, +) + +from .._sql_log import REDACTED + +if TYPE_CHECKING: + from typing import Self + +__all__ = ["REDACTED", "RenderedSql", "Terminal", "TerminalMethod", "send", "terminal"] + +S = TypeVar("S") +P = ParamSpec("P") +R = TypeVar("R") +R_co = TypeVar("R_co", covariant=True) + +_RenderedParts = tuple[str, tuple[object, ...], tuple[bool, ...], str] +"""What an engine rendering entry returns: the SQL, its parameters (`None` +where masked), the mask (`True` where the parameter is a secret) and the +dialect.""" + + +@dataclass(frozen=True, slots=True) +class RenderedSql: + """One statement a query terminal would send, as the statement log records it. + + `str()` of it is the SQL alone, so `print(rendered)` shows the statement. + + Examples: + ```python {test=run prelude=reference} + rendered = await Author.where(lambda author: author.id == 1).all.sql() + print(rendered.dialect, rendered.params) + ``` + """ + + sql: str + """The SQL text, with the dialect's placeholders (`$1` or `?`).""" + params: tuple[object, ...] + """The bound values in placeholder order; a secret value is + [`REDACTED`][ferro.REDACTED].""" + dialect: Literal["postgres", "sqlite"] + """The dialect of the database the call would run on.""" + + def __str__(self) -> str: + """Return the SQL alone.""" + return self.sql + + +_DIALECTS: dict[str, Literal["postgres", "sqlite"]] = { + "postgres": "postgres", + "sqlite": "sqlite", +} +"""The dialect names the engine renders for, as `RenderedSql.dialect` types them.""" + +_rendering: ContextVar[bool] = ContextVar("ferro_rendering", default=False) +"""Whether the running terminal is rendering (`.sql()`) rather than sending.""" + + +class _Rendered(Exception): + """Carries a terminal's rendered statement out of its method body. + + Raised where the method would have sent its statement, so nothing after + the send (decoding, the identity map, the result's post-processing) runs + when rendering. + """ + + def __init__(self, rendered: RenderedSql) -> None: + super().__init__(rendered.sql) + self.rendered = rendered + + +def send( + execute: Callable[P, Awaitable[R]], + render: Callable[P, Awaitable[_RenderedParts]], +) -> Callable[P, Awaitable[R]]: + """Pair an engine entry that sends a statement with its rendering twin. + + A terminal's method sends its statement through this pair. Called + normally, it runs `execute`. Called from `.sql()`, it runs `render` with + the same arguments and hands the rendered statement back to `.sql()`. + + Args: + execute: The engine entry that builds and sends the statement. + render: The engine entry that builds the same statement and returns + it without sending it. + + Returns: + A callable with `execute`'s signature. + """ + + @functools.wraps(execute) + async def call(*args: P.args, **kwargs: P.kwargs) -> R: + if not _rendering.get(): + return await execute(*args, **kwargs) + sql, params, mask, dialect = await render(*args, **kwargs) + raise _Rendered( + RenderedSql( + sql=sql, + params=tuple( + REDACTED if masked else value + for value, masked in zip(params, mask, strict=True) + ), + dialect=_DIALECTS[dialect], + ) + ) + + return call + + +class Terminal(Generic[P, R_co]): + """A query terminal bound to its query: awaiting a call runs it, `.sql()` renders it.""" + + __slots__ = ("_method", "_query") + + def __init__(self, method: Callable[..., Awaitable[R_co]], query: object) -> None: + self._method = method + self._query = query + + def __call__(self, *args: P.args, **kwargs: P.kwargs) -> Awaitable[R_co]: + """Run the terminal: send its statement and return its result.""" + return self._method(self._query, *args, **kwargs) + + async def sql(self, *args: P.args, **kwargs: P.kwargs) -> RenderedSql: + """Render the statement this terminal would send, without sending it. + + Takes exactly the arguments the terminal takes and routes like the + call: the enclosing session, `using=` and `session=` pick the + database. On Postgres it may read the table's column types once, the + way the call would; it never sends the statement itself, opens no + transaction and changes no row. + + Args: + *args: The terminal's positional arguments. + **kwargs: The terminal's keyword arguments. + + Returns: + The SQL, parameters and dialect the call would send, as the + statement log would record them, with each secret value shown + as [`REDACTED`][ferro.REDACTED]. + + Raises: + RuntimeError: No database route: the call is outside a session + and no connection was named. + TypeError: The arguments are ones the terminal rejects. + + Examples: + ```python {test=run prelude=reference} + rendered = await Author.where(lambda author: author.id == 1).all.sql() + print(rendered) + ``` + """ + token = _rendering.set(True) + try: + await self._method(self._query, *args, **kwargs) + except _Rendered as rendered: + return rendered.rendered + finally: + _rendering.reset(token) + raise RuntimeError( + f"{getattr(self._method, '__qualname__', self._method)!r} returned " + "without sending a statement, so there is nothing to render" + ) + + def __repr__(self) -> str: + return f"" + + +class TerminalMethod(Generic[S, P, R_co]): + """A query terminal on its class: reading it from a query binds a [`Terminal`][ferro.query.rendered.Terminal].""" + + def __init__(self, method: Callable[Concatenate[S, P], Awaitable[R_co]]) -> None: + self._method = method + functools.update_wrapper(self, method) + + @overload + def __get__(self, query: None, owner: type[Any]) -> Self: ... + + @overload + def __get__(self, query: S, owner: type[Any]) -> Terminal[P, R_co]: ... + + def __get__(self, query: S | None, owner: type[Any]) -> Self | Terminal[P, R_co]: + if query is None: + return self + return Terminal(self._method, query) + + def __call__(self, query: S, *args: P.args, **kwargs: P.kwargs) -> Awaitable[R_co]: + """Run the terminal on `query`, read from the class.""" + return self._method(query, *args, **kwargs) + + +def terminal( + method: Callable[Concatenate[S, P], Awaitable[R]], +) -> TerminalMethod[S, P, R]: + """Make a query method a terminal: callable to run, `.sql()` to render. + + The method sends its statement through [`send`][ferro.query.rendered.send]; + `.sql()` runs the same method with that send swapped for its rendering + twin, so the call and the rendering share every argument check, the + routing and the statement build. + + Args: + method: The `async def` query method, or a method returning another + terminal's awaitable. + + Returns: + The terminal, read from a query as a bound + [`Terminal`][ferro.query.rendered.Terminal]. + """ + return TerminalMethod(method) diff --git a/src/lib.rs b/src/lib.rs index f9905af9..7c34b0b6 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -135,6 +135,10 @@ fn _core(m: &Bound<'_, PyModule>) -> PyResult<()> { m.add_function(wrap_pyfunction!(operations::fetch_all, m)?)?; m.add_function(wrap_pyfunction!(operations::fetch_filtered, m)?)?; m.add_function(wrap_pyfunction!(operations::count_filtered, m)?)?; + m.add_function(wrap_pyfunction!(operations::render_fetch, m)?)?; + m.add_function(wrap_pyfunction!(operations::render_count, m)?)?; + m.add_function(wrap_pyfunction!(operations::render_update, m)?)?; + m.add_function(wrap_pyfunction!(operations::render_delete, m)?)?; m.add_function(wrap_pyfunction!(operations::fetch_one, m)?)?; m.add_function(wrap_pyfunction!(operations::register_instance, m)?)?; m.add_function(wrap_pyfunction!(operations::evict_instance, m)?)?; diff --git a/src/operations.rs b/src/operations.rs index 1584a94d..c94b459d 100644 --- a/src/operations.rs +++ b/src/operations.rs @@ -1382,6 +1382,24 @@ fn engine_bind_values_from_sea(values: &[SeaValue]) -> Vec { .collect() } +/// One statement as an operation builds it: the SQL and its binds in +/// placeholder order. What an executing entry sends and its rendering twin +/// returns, from the same `build_*` function. +#[derive(Debug, Clone, PartialEq)] +struct BuiltStatement { + sql: String, + binds: Vec, +} + +impl BuiltStatement { + fn from_sea(sql: String, values: &sea_query::Values) -> Self { + Self { + sql, + binds: engine_bind_values_from_sea(&values.0), + } + } +} + /// The statement-log context an operation entry opens (ADR-0057), or `None` /// when `ferro.sql` is not enabled for `DEBUG`. Asked once, while the entry /// holds the GIL; `secret_values` is called only when the log is on, so an @@ -3275,45 +3293,30 @@ mod bulk_chunking_tests { } } -/// Fetches records for a given model class based on a QueryIR-defined query. -/// -/// The query's materialization plan (ADR-0007) selects the result shape: -/// `root_instances` hydrates complete model instances (identity-map aware); -/// a `record` plan renders the projected SELECT list and hydrates -/// `record_cls` records (#279) — no identity map, no persistence identity; -/// an `instances` plan widens the SELECT with every included hop's complete -/// aliased row and hydrates a populated instance graph (#286, ADR-0008). -/// -/// Args: -/// cls (PyAny): The Python model class. -/// query_ir_json (str): The serialized QueryIR envelope JSON. -/// record_cls (PyAny | None): Record constructor for a `record` plan -/// (`Row` today; the seam a future `into=` plugs into). Required for -/// a record plan, forbidden otherwise. -/// hop_classes (dict[str, type] | None): Included hop model classes keyed -/// by physical table name, for an `instances` plan. Required for an -/// instances plan, forbidden otherwise. -/// -/// Returns: -/// list[PyAny]: Hydrated model instances (populated when included), or -/// projected records. -#[pyfunction] -#[pyo3(signature = ( - cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() -))] -pub fn fetch_filtered<'py>( - py: Python<'py>, - cls: Bound<'py, PyAny>, - query_ir_json: String, - route: Py, - record_cls: Option>, - hop_classes: Option>, - secret_values: Vec>, -) -> PyResult> { - let name = crate::state::model_identity(&cls)?; - let cls_py = cls.unbind(); +/// What a fetch carries besides its statement: the plan's include paths +/// and projected fields, and the record constructor and hop classes the +/// call passed, checked against the plan. Decided once, here, for the +/// executing entry and its rendering twin alike, so both refuse the same +/// calls with the same errors. +struct FetchRequest { + include_paths: Option>>, + projected: Option>, + record_cls_py: Option>, + hop_classes_py: Option>, +} - let mut plan = query_plan_from_ir_json(&query_ir_json)?; +/// Parse and check a fetch's plan, and pair the call's `record_cls` and +/// `hop_classes` with it. +/// +/// # Errors +/// `PyValueError` for a malformed or unsupported plan, or a constructor or +/// hop-class map the plan does not call for (or lacks). +fn fetch_request( + query_ir_json: &str, + record_cls: Option>, + hop_classes: Option>, +) -> PyResult<(QueryPlan, FetchRequest)> { + let plan = query_plan_from_ir_json(query_ir_json)?; validate_paging_shape(&plan, "fetch")?; validate_set_shape(&plan, "fetch")?; let include_paths: Option>> = match &plan.materialization { @@ -3376,6 +3379,207 @@ pub fn fetch_filtered<'py>( )); } }; + Ok(( + plan, + FetchRequest { + include_paths, + projected, + record_cls_py, + hop_classes_py, + }, + )) +} + +/// A fetch's statement, and what decoding its rows needs. +struct BuiltFetch { + statement: BuiltStatement, + /// The root model's registration: its codec plan and primary key. + schema: Arc, + join_plan: JoinPlan, + include_hops: Vec, +} + +/// Build the SELECT a fetch sends: the one build both +/// [`fetch_filtered`] (which sends it) and [`render_fetch`] (which returns +/// it) use. On Postgres it reads the root's and each hop table's cached +/// catalog (probing on first touch) so the binds carry the casts the +/// database needs. +/// +/// # Errors +/// `PyRuntimeError` for an unregistered model or a failed catalog probe; +/// `PyValueError` for a relation path, order key or paging bound the plan +/// cannot render. +async fn build_fetch( + plan: &mut QueryPlan, + name: &str, + include_paths: Option<&[Vec]>, + projected: Option<&[ProjectedField]>, + engine: &EngineHandle, + exec: Executor<'_>, + backend: Dialect, +) -> PyResult { + let schema = crate::state::registered_model(name)?; + let table_name = schema.table_name.clone(); + let catalog = postgres_table_catalog(&table_name, engine, exec, backend).await?; + plan.postgres_enum_udt = catalog.enum_udt.clone(); + + // Relation-traversal JOINs (#270): the M2M association table (when + // present) is reserved so a relation alias can never collide with it. + // The join plan is built up front so each hop table's registration + + // enum catalog can be resolved before conditions bind (#270 critical). + let m2m_join_table = plan.m2m.as_ref().map(|m2m| m2m.join_table.clone()); + let reserved: Vec<&str> = m2m_join_table.as_deref().into_iter().collect(); + let join_plan = query_join_plan(plan, &table_name, &reserved)?; + populate_hop_bind_context(plan, &join_plan, engine, exec, backend).await?; + // Included hops (#286): resolved after the bind context, so every + // include-edge table's registration is already in place. + let include_hops = match include_paths { + Some(paths) => resolve_include_hops(paths, &join_plan, plan)?, + None => Vec::new(), + }; + let statement = { + let pk = schema.meta.pk_col.clone(); + + let mut select = Query::select(); + apply_select_list( + &mut select, + &table_name, + &schema.column_names, + projected, + &join_plan, + )?; + apply_include_select_list(&mut select, &include_hops); + select.from(Alias::new(&table_name)); + + if let Some(m2m) = &plan.m2m { + let join_table = Alias::new(&m2m.join_table); + let source_col = Alias::new(&m2m.source_col); + let target_col = Alias::new(&m2m.target_col); + let pk_name = pk.as_ref().ok_or_else(|| { + pyo3::exceptions::PyRuntimeError::new_err("No primary key for M2M join") + })?; + + select.inner_join( + join_table.clone(), + Expr::col((Alias::new(&table_name), Alias::new(pk_name))) + .equals((join_table.clone(), target_col.clone())), + ); + select.and_where(Expr::col((join_table.clone(), source_col.clone())).eq( + plan.value_rhs_simple_expr_for_backend( + &m2m.source_col, + &m2m.source_id, + true, + backend, + ), + )); + } + + apply_relation_joins(&mut select, &join_plan)?; + + // WHERE columns are qualified by their relation-path alias (root leaf -> + // root table, path leaf -> its JOIN alias). A path with no matching join + // entry is a loud error, never a silently unqualified column. + let mut condition = query_condition_with_joins(plan, backend, &table_name, &join_plan)?; + if let Some(after) = plan + .after_condition(backend, &table_name, &join_plan) + .map_err(pyo3::exceptions::PyValueError::new_err)? + { + condition = condition.add(after); + } + if let Some(before) = plan + .before_condition(backend, &table_name, &join_plan) + .map_err(pyo3::exceptions::PyValueError::new_err)? + { + condition = condition.add(before); + } + select.cond_where(condition); + // ORDER BY terms are qualified the same way as WHERE leaves: an empty + // path qualifies by the root table, a relation path by its JOIN alias + // (#271). A path with no matching join entry is a loud error — the + // Python builder always registers the join for an order_by path, so + // this is defense-in-depth, never reachable in normal use. On a + // record plan the term resolves output field names FIRST (#295): + // a matching name renders as the bare result-column alias. + // `before` inverts direction and first↔last (`native` stays + // `native`) so LIMIT n fetches the adjacent previous page (#395). + let order_by = plan + .order_by_for_select() + .map_err(pyo3::exceptions::PyValueError::new_err)?; + for order in &order_by { + let col = match projected { + Some(fields) => record_order_by_expr(order, fields, &table_name, &join_plan)?, + None => crate::query::qualify_column_with_joins( + &table_name, + &join_plan, + &order.column, + &order.path, + ) + .map_err(pyo3::exceptions::PyValueError::new_err)?, + }; + apply_order_by_term(&mut select, col.into(), order)?; + } + if let Some(limit) = plan.limit.flatten() { + select.limit(limit); + } + if let Some(offset) = plan.offset.flatten() { + select.offset(offset); + } + let (sql, values) = sea_query_build_for_backend!(select, backend); + BuiltStatement::from_sea(sql, &values) + }; + + Ok(BuiltFetch { + statement, + schema, + join_plan, + include_hops, + }) +} + +/// Fetches records for a given model class based on a QueryIR-defined query. +/// +/// The query's materialization plan (ADR-0007) selects the result shape: +/// `root_instances` hydrates complete model instances (identity-map aware); +/// a `record` plan renders the projected SELECT list and hydrates +/// `record_cls` records (#279) — no identity map, no persistence identity; +/// an `instances` plan widens the SELECT with every included hop's complete +/// aliased row and hydrates a populated instance graph (#286, ADR-0008). +/// +/// Args: +/// cls (PyAny): The Python model class. +/// query_ir_json (str): The serialized QueryIR envelope JSON. +/// record_cls (PyAny | None): Record constructor for a `record` plan +/// (`Row` today; the seam a future `into=` plugs into). Required for +/// a record plan, forbidden otherwise. +/// hop_classes (dict[str, type] | None): Included hop model classes keyed +/// by physical table name, for an `instances` plan. Required for an +/// instances plan, forbidden otherwise. +/// +/// Returns: +/// list[PyAny]: Hydrated model instances (populated when included), or +/// projected records. +#[pyfunction] +#[pyo3(signature = ( + cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() +))] +pub fn fetch_filtered<'py>( + py: Python<'py>, + cls: Bound<'py, PyAny>, + query_ir_json: String, + route: Py, + record_cls: Option>, + hop_classes: Option>, + secret_values: Vec>, +) -> PyResult> { + let name = crate::state::model_identity(&cls)?; + let (mut plan, request) = fetch_request(&query_ir_json, record_cls, hop_classes)?; + let FetchRequest { + include_paths, + projected, + record_cls_py, + hop_classes_py, + } = request; + let cls_py = cls.unbind(); let log = operation_log(py, "fetch", &route.get().connection_name, |py| { operation_secret_values( &secret_values, @@ -3400,124 +3604,24 @@ pub fn fetch_filtered<'py>( let outcome = async { let use_identity_map = engine.is_identity_map_enabled(); - - let schema = crate::state::registered_model(&name)?; - let table_name = schema.table_name.clone(); - let catalog = postgres_table_catalog(&table_name, &engine, exec, backend).await?; - plan.postgres_enum_udt = catalog.enum_udt.clone(); - - // Relation-traversal JOINs (#270): the M2M association table (when - // present) is reserved so a relation alias can never collide with it. - // The join plan is built up front so each hop table's registration + - // enum catalog can be resolved before conditions bind (#270 critical). - let m2m_join_table = plan.m2m.as_ref().map(|m2m| m2m.join_table.clone()); - let reserved: Vec<&str> = m2m_join_table.as_deref().into_iter().collect(); - let join_plan = query_join_plan(&plan, &table_name, &reserved)?; - populate_hop_bind_context(&mut plan, &join_plan, &engine, exec, backend).await?; - // Included hops (#286): resolved after the bind context, so every - // include-edge table's registration is already in place. - let include_hops = match &include_paths { - Some(paths) => resolve_include_hops(paths, &join_plan, &plan)?, - None => Vec::new(), - }; - // ... - let (sql, bind_values, pk_col, schema_for_decode) = { - let pk = schema.meta.pk_col.clone(); - - let mut select = Query::select(); - apply_select_list( - &mut select, - &table_name, - &schema.column_names, - projected.as_deref(), - &join_plan, - )?; - apply_include_select_list(&mut select, &include_hops); - select.from(Alias::new(&table_name)); - - if let Some(m2m) = &plan.m2m { - let join_table = Alias::new(&m2m.join_table); - let source_col = Alias::new(&m2m.source_col); - let target_col = Alias::new(&m2m.target_col); - let pk_name = pk.as_ref().ok_or_else(|| { - pyo3::exceptions::PyRuntimeError::new_err("No primary key for M2M join") - })?; - - select.inner_join( - join_table.clone(), - Expr::col((Alias::new(&table_name), Alias::new(pk_name))) - .equals((join_table.clone(), target_col.clone())), - ); - select.and_where(Expr::col((join_table.clone(), source_col.clone())).eq( - plan.value_rhs_simple_expr_for_backend( - &m2m.source_col, - &m2m.source_id, - true, - backend, - ), - )); - } - - apply_relation_joins(&mut select, &join_plan)?; - - // WHERE columns are qualified by their relation-path alias (root leaf -> - // root table, path leaf -> its JOIN alias). A path with no matching join - // entry is a loud error, never a silently unqualified column. - let mut condition = - query_condition_with_joins(&plan, backend, &table_name, &join_plan)?; - if let Some(after) = plan - .after_condition(backend, &table_name, &join_plan) - .map_err(pyo3::exceptions::PyValueError::new_err)? - { - condition = condition.add(after); - } - if let Some(before) = plan - .before_condition(backend, &table_name, &join_plan) - .map_err(pyo3::exceptions::PyValueError::new_err)? - { - condition = condition.add(before); - } - select.cond_where(condition); - // ORDER BY terms are qualified the same way as WHERE leaves: an empty - // path qualifies by the root table, a relation path by its JOIN alias - // (#271). A path with no matching join entry is a loud error — the - // Python builder always registers the join for an order_by path, so - // this is defense-in-depth, never reachable in normal use. On a - // record plan the term resolves output field names FIRST (#295): - // a matching name renders as the bare result-column alias. - // `before` inverts direction and first↔last (`native` stays - // `native`) so LIMIT n fetches the adjacent previous page (#395). - let order_by = plan - .order_by_for_select() - .map_err(pyo3::exceptions::PyValueError::new_err)?; - for order in &order_by { - let col = match projected.as_deref() { - Some(fields) => { - record_order_by_expr(order, fields, &table_name, &join_plan)? - } - None => crate::query::qualify_column_with_joins( - &table_name, - &join_plan, - &order.column, - &order.path, - ) - .map_err(pyo3::exceptions::PyValueError::new_err)?, - }; - apply_order_by_term(&mut select, col.into(), order)?; - } - if let Some(limit) = plan.limit.flatten() { - select.limit(limit); - } - if let Some(offset) = plan.offset.flatten() { - select.offset(offset); - } - let (s, values) = sea_query_build_for_backend!(select, backend); - (s, values, pk, schema.clone()) - }; - - let engine_bind_values = engine_bind_values_from_sea(&bind_values.0); + let BuiltFetch { + statement, + schema: schema_for_decode, + join_plan, + include_hops, + } = build_fetch( + &mut plan, + &name, + include_paths.as_deref(), + projected.as_deref(), + &engine, + exec, + backend, + ) + .await?; + let pk_col = schema_for_decode.meta.pk_col.clone(); let rows = exec - .fetch_all(&sql, &engine_bind_values) + .fetch_all(&statement.sql, &statement.binds) .await .map_err(|e| crate::errors::map_db_error("Fetch failed", e))?; // A record plan skips PK extraction entirely: projected records carry @@ -3764,6 +3868,109 @@ pub fn fetch_filtered<'py>( pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } +/// Parse and check a count's plan, and name its statement-log records: +/// `"count"`, or `"exists"` when the count answers `exists()`. +/// +/// # Errors +/// `PyValueError` for an unknown `operation` or a plan a count cannot run. +fn count_plan(query_ir_json: &str, operation: &str) -> PyResult<(QueryPlan, &'static str)> { + let operation: &'static str = match operation { + "count" => "count", + "exists" => "exists", + other => { + return Err(pyo3::exceptions::PyValueError::new_err(format!( + "count_filtered operation must be 'count' or 'exists', got {other:?}" + ))); + } + }; + let plan = query_plan_from_ir_json(query_ir_json)?; + validate_paging_shape(&plan, "count")?; + validate_set_shape(&plan, "count")?; + // count() is unaffected by projection (PRD #277 verb table): the Python + // builder always emits root_instances on count payloads, projected or not. + reject_unsupported_materialization(&plan, "count_filtered")?; + Ok((plan, operation)) +} + +/// Build the `SELECT COUNT(*)` that `count()` and `exists()` send: the +/// one build [`count_filtered`] and [`render_count`] share. On Postgres +/// it reads the root's and each hop table's cached catalog. +/// +/// # Errors +/// `PyRuntimeError` for an unregistered model or a failed catalog probe; +/// `PyTypeError` / `PyValueError` for a value or relation path the plan +/// cannot render. +async fn build_count( + plan: &mut QueryPlan, + name: &str, + engine: &EngineHandle, + exec: Executor<'_>, + backend: Dialect, +) -> PyResult { + let schema = crate::state::registered_model(name)?; + let table_name = schema.table_name.clone(); + plan.postgres_enum_udt = postgres_table_catalog(&table_name, engine, exec, backend) + .await? + .enum_udt + .clone(); + + // Relation-traversal JOINs render into the COUNT the same as the SELECT + // (#270). Plain COUNT(*), no DISTINCT: forward-FK hops are many-to-one and + // never multiply root rows, so count() equals the matching root-row count. + // Build the plan up front and resolve each hop table's registration + + // enum catalog before conditions bind (#270 critical). + let m2m_join_table = plan.m2m.as_ref().map(|m2m| m2m.join_table.clone()); + let reserved: Vec<&str> = m2m_join_table.as_deref().into_iter().collect(); + let join_plan = query_join_plan(plan, &table_name, &reserved)?; + populate_hop_bind_context(plan, &join_plan, engine, exec, backend).await?; + let (sql, values) = { + let mut select = Query::select(); + select.expr(Expr::cust("COUNT(*)")); + + if let Some(m2m) = &plan.m2m { + let join_table = Alias::new(&m2m.join_table); + let source_col = Alias::new(&m2m.source_col); + let target_col = Alias::new(&m2m.target_col); + + // We need the PK name of the target table to join + let pk_name = schema + .meta + .pk_col + .clone() + .ok_or_else(|| pyo3::exceptions::PyRuntimeError::new_err("No primary key"))?; + + select.from(Alias::new(&table_name)); + select.inner_join( + join_table.clone(), + Expr::col((Alias::new(&table_name), Alias::new(pk_name))) + .equals((join_table.clone(), target_col.clone())), + ); + select.and_where(Expr::col((join_table.clone(), source_col.clone())).eq( + plan.value_rhs_simple_expr_for_backend( + &m2m.source_col, + &m2m.source_id, + true, + backend, + ), + )); + } else { + select.from(Alias::new(&table_name)); + } + + apply_relation_joins(&mut select, &join_plan)?; + + // WHERE columns qualified by their relation-path alias (see fetch_filtered). + select.cond_where(query_condition_with_joins( + plan, + backend, + &table_name, + &join_plan, + )?); + sea_query_build_for_backend!(select, backend) + }; + Ok(BuiltStatement::from_sea(sql, &values)) +} + /// Return the number of rows matching a filtered query. /// /// Args: @@ -3793,21 +4000,7 @@ pub fn count_filtered<'py>( secret_values: Vec>, operation: &str, ) -> PyResult> { - let operation: &'static str = match operation { - "count" => "count", - "exists" => "exists", - other => { - return Err(pyo3::exceptions::PyValueError::new_err(format!( - "count_filtered operation must be 'count' or 'exists', got {other:?}" - ))); - } - }; - let mut plan = query_plan_from_ir_json(&query_ir_json)?; - validate_paging_shape(&plan, "count")?; - validate_set_shape(&plan, "count")?; - // count() is unaffected by projection (PRD #277 verb table): the Python - // builder always emits root_instances on count payloads, projected or not. - reject_unsupported_materialization(&plan, "count_filtered")?; + let (mut plan, operation) = count_plan(&query_ir_json, operation)?; let log = operation_log(py, operation, &route.get().connection_name, |py| { operation_secret_values( &secret_values, @@ -3830,70 +4023,9 @@ pub fn count_filtered<'py>( let exec = Executor::new(scope.connection(), &engine); let outcome = async { - let schema = crate::state::registered_model(&name)?; - let table_name = schema.table_name.clone(); - plan.postgres_enum_udt = postgres_table_catalog(&table_name, &engine, exec, backend) - .await? - .enum_udt - .clone(); - - // Relation-traversal JOINs render into the COUNT the same as the SELECT - // (#270). Plain COUNT(*), no DISTINCT: forward-FK hops are many-to-one and - // never multiply root rows, so count() equals the matching root-row count. - // Build the plan up front and resolve each hop table's registration + - // enum catalog before conditions bind (#270 critical). - let m2m_join_table = plan.m2m.as_ref().map(|m2m| m2m.join_table.clone()); - let reserved: Vec<&str> = m2m_join_table.as_deref().into_iter().collect(); - let join_plan = query_join_plan(&plan, &table_name, &reserved)?; - populate_hop_bind_context(&mut plan, &join_plan, &engine, exec, backend).await?; - // ... sql ... - let (sql, bind_values) = { - let mut select = Query::select(); - select.expr(Expr::cust("COUNT(*)")); - - if let Some(m2m) = &plan.m2m { - let join_table = Alias::new(&m2m.join_table); - let source_col = Alias::new(&m2m.source_col); - let target_col = Alias::new(&m2m.target_col); - - // We need the PK name of the target table to join - let pk_name = schema.meta.pk_col.clone().ok_or_else(|| { - pyo3::exceptions::PyRuntimeError::new_err("No primary key") - })?; - - select.from(Alias::new(&table_name)); - select.inner_join( - join_table.clone(), - Expr::col((Alias::new(&table_name), Alias::new(pk_name))) - .equals((join_table.clone(), target_col.clone())), - ); - select.and_where(Expr::col((join_table.clone(), source_col.clone())).eq( - plan.value_rhs_simple_expr_for_backend( - &m2m.source_col, - &m2m.source_id, - true, - backend, - ), - )); - } else { - select.from(Alias::new(&table_name)); - } - - apply_relation_joins(&mut select, &join_plan)?; - - // WHERE columns qualified by their relation-path alias (see fetch_filtered). - select.cond_where(query_condition_with_joins( - &plan, - backend, - &table_name, - &join_plan, - )?); - sea_query_build_for_backend!(select, backend) - }; - - let engine_bind_values = engine_bind_values_from_sea(&bind_values.0); + let statement = build_count(&mut plan, &name, &engine, exec, backend).await?; let rows = exec - .fetch_all(&sql, &engine_bind_values) + .fetch_all(&statement.sql, &statement.binds) .await .map_err(|e| crate::errors::map_db_error("Count failed", e))?; let count = rows @@ -4037,6 +4169,58 @@ pub fn delete_record( pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } +/// Parse and check a query delete's plan. +/// +/// # Errors +/// `PyValueError` for a plan a delete cannot run: paging, a traversal, a +/// projection or a `SET`. +fn delete_plan(query_ir_json: &str) -> PyResult { + let plan = query_plan_from_ir_json(query_ir_json)?; + validate_set_shape(&plan, "delete")?; + validate_paging_shape(&plan, "delete")?; + reject_traversal_on_mutation(&plan, "delete")?; + reject_unsupported_materialization(&plan, "delete")?; + Ok(plan) +} + +/// Build the `DELETE` a query's `delete()` sends: the one build +/// [`delete_filtered`] and [`render_delete`] share. On Postgres it reads +/// the table's cached catalog. +/// +/// # Errors +/// `PyRuntimeError` for an unregistered model or a failed catalog probe; +/// `PyTypeError` / `PyValueError` for a value or relation path the plan +/// cannot render. +async fn build_delete( + plan: &mut QueryPlan, + name: &str, + engine: &EngineHandle, + exec: Executor<'_>, + backend: Dialect, +) -> PyResult { + let table_name = crate::state::registered_model(name)?.table_name.clone(); + plan.postgres_enum_udt = postgres_table_catalog(&table_name, engine, exec, backend) + .await? + .enum_udt + .clone(); + let (sql, values) = { + let mut delete = Query::delete(); + // Qualified by the root table alias (#269): both dialects accept + // `table.column` in `DELETE ... WHERE`, and uniform qualification across + // every walker avoids retrofitting the mutating paths when joins reach + // them later. + delete + .from_table(Alias::new(&table_name)) + .cond_where(query_condition_for_backend( + plan, + backend, + Some(&table_name), + )?); + sea_query_build_for_backend!(delete, backend) + }; + Ok(BuiltStatement::from_sea(sql, &values)) +} + /// Delete rows matching a filtered query. /// /// Args: @@ -4060,11 +4244,7 @@ pub fn delete_filtered<'py>( route: Py, secret_values: Vec>, ) -> PyResult> { - let mut plan = query_plan_from_ir_json(&query_ir_json)?; - validate_set_shape(&plan, "delete")?; - validate_paging_shape(&plan, "delete")?; - reject_traversal_on_mutation(&plan, "delete")?; - reject_unsupported_materialization(&plan, "delete")?; + let mut plan = delete_plan(&query_ir_json)?; let log = operation_log(py, "delete", &route.get().connection_name, |py| { operation_secret_values( &secret_values, @@ -4088,33 +4268,11 @@ pub fn delete_filtered<'py>( let exec = Executor::new(scope.connection(), &engine); let outcome = async { - let table_name = crate::state::registered_model(&name)?.table_name.clone(); - plan.postgres_enum_udt = postgres_table_catalog(&table_name, &engine, exec, backend) - .await? - .enum_udt - .clone(); - // ... sql ... - let (sql, bind_values) = - { - let mut delete = Query::delete(); - // Qualified by the root table alias (#269): both dialects accept - // `table.column` in `DELETE ... WHERE`, and uniform qualification across - // every walker avoids retrofitting the mutating paths when joins reach - // them later. - delete.from_table(Alias::new(&table_name)).cond_where( - query_condition_for_backend(&plan, backend, Some(&table_name))?, - ); - sea_query_build_for_backend!(delete, backend) - }; - - let rows_affected = execute_statement_with_optional_tx( - &engine, - scope.connection(), - &sql, - &bind_values.0, - ) - .await - .map_err(|e| crate::errors::map_db_error("Delete failed", e))?; + let statement = build_delete(&mut plan, &name, &engine, exec, backend).await?; + let rows_affected = exec + .execute(&statement.sql, &statement.binds) + .await + .map_err(|e| crate::errors::map_db_error("Delete failed", e))?; // After bulk delete, we MUST clear the Identity Map for this model to avoid stale objects // Re-acquire the GIL before accessing identity map (async context has no GIL). @@ -4133,6 +4291,85 @@ pub fn delete_filtered<'py>( pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } +/// Parse and check a query update's plan against the model it names. +/// +/// # Errors +/// `PyValueError` for a plan an update cannot run (no `SET`, paging, a +/// traversal, a projection) or one declaring another model than `name`. +fn update_plan(name: &str, query_ir_json: &str) -> PyResult { + let plan = query_plan_from_ir_json(query_ir_json)?; + validate_set_shape(&plan, "update")?; + if name != plan.model_name { + return Err(pyo3::exceptions::PyValueError::new_err(format!( + "update model identity mismatch: argument {name:?}, QueryIR declares {:?}", + plan.model_name + ))); + } + validate_paging_shape(&plan, "update")?; + reject_traversal_on_mutation(&plan, "update")?; + reject_unsupported_materialization(&plan, "update")?; + Ok(plan) +} + +/// Build the `UPDATE` a query's `update()` sends, from either form (the +/// keyword literals or the recipe, both already in the plan's `SET`): +/// the one build [`update_filtered`] and [`render_update`] share. On +/// Postgres it reads the table's cached catalog, whose column types +/// decide the `SET` binds' casts. +/// +/// # Errors +/// `PyRuntimeError` for an unregistered model or a failed catalog probe; +/// `PyTypeError` / `PyValueError` for a value or relation path the plan +/// cannot render. +async fn build_update( + plan: &mut QueryPlan, + name: &str, + engine: &EngineHandle, + exec: Executor<'_>, + backend: Dialect, +) -> PyResult { + let schema = crate::state::registered_model(name)?; + let table_name = schema.table_name.clone(); + let catalog = postgres_table_catalog(&table_name, engine, exec, backend).await?; + let TableCatalog { + enum_udt, + uuid_columns, + ts_cast, + } = &*catalog; + plan.postgres_enum_udt = enum_udt.clone(); + let (sql, values) = { + // Qualified by the root table alias (#269) — same rationale as + // `delete_filtered` above. SET columns stay bare: SQL forbids + // qualified column names on the left of `SET` assignments. + let mut update = UpdateStatement::new() + .table(Alias::new(&table_name)) + .cond_where(query_condition_for_backend( + plan, + backend, + Some(&table_name), + )?) + .to_owned(); + for assignment in &plan.set_assignments { + let key = &assignment.column; + update.value( + Alias::new(key), + set_value_to_expr( + &schema, + &table_name, + key, + &assignment.value, + enum_udt, + uuid_columns, + ts_cast, + backend, + )?, + ); + } + sea_query_build_for_backend!(update, backend) + }; + Ok(BuiltStatement::from_sea(sql, &values)) +} + /// Update rows matching a filtered query using its canonical QueryIR SET section. /// /// Args: @@ -4156,17 +4393,7 @@ pub fn update_filtered<'py>( route: Py, secret_values: Vec>, ) -> PyResult> { - let mut plan = query_plan_from_ir_json(&query_ir_json)?; - validate_set_shape(&plan, "update")?; - if name != plan.model_name { - return Err(pyo3::exceptions::PyValueError::new_err(format!( - "update model identity mismatch: argument {name:?}, QueryIR declares {:?}", - plan.model_name - ))); - } - validate_paging_shape(&plan, "update")?; - reject_traversal_on_mutation(&plan, "update")?; - reject_unsupported_materialization(&plan, "update")?; + let mut plan = update_plan(&name, &query_ir_json)?; let log = operation_log(py, "update", &route.get().connection_name, |py| { operation_secret_values( &secret_values, @@ -4189,55 +4416,11 @@ pub fn update_filtered<'py>( let exec = Executor::new(scope.connection(), &engine); let outcome = async { - let schema = crate::state::registered_model(&name)?; - let table_name = schema.table_name.clone(); - let catalog = postgres_table_catalog(&table_name, &engine, exec, backend).await?; - let TableCatalog { - enum_udt, - uuid_columns, - ts_cast, - } = &*catalog; - plan.postgres_enum_udt = enum_udt.clone(); - // ... sql ... - let (sql, bind_values) = { - // Qualified by the root table alias (#269) — same rationale as - // `delete_filtered` above. SET columns stay bare: SQL forbids - // qualified column names on the left of `SET` assignments. - let mut update = UpdateStatement::new() - .table(Alias::new(&table_name)) - .cond_where(query_condition_for_backend( - &plan, - backend, - Some(&table_name), - )?) - .to_owned(); - for assignment in &plan.set_assignments { - let key = &assignment.column; - update.value( - Alias::new(key), - set_value_to_expr( - &schema, - &table_name, - key, - &assignment.value, - enum_udt, - uuid_columns, - ts_cast, - backend, - )?, - ); - } - sea_query_build_for_backend!(update, backend) - }; - - let rows_affected = execute_statement_with_optional_tx( - &engine, - scope.connection(), - &sql, - &bind_values.0, - ) - .await - .map_err(|e| crate::errors::map_db_error("Update failed", e))?; + let statement = build_update(&mut plan, &name, &engine, exec, backend).await?; + let rows_affected = exec + .execute(&statement.sql, &statement.binds) + .await + .map_err(|e| crate::errors::map_db_error("Update failed", e))?; // After bulk update, we MUST clear the Identity Map for this model to avoid stale objects // Re-acquire the GIL before accessing identity map (async context has no GIL). @@ -4256,6 +4439,226 @@ pub fn update_filtered<'py>( pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, operation)) } +/// A rendering entry's answer: the statement's SQL, its parameters as the +/// statement log shows them (`None` where masked), the mask and the +/// dialect's name. +/// +/// # Errors +/// The `PyErr` from converting a bind to Python. +fn rendered_parts( + statement: &BuiltStatement, + secrets: &[EngineBindValue], + backend: Dialect, +) -> PyResult> { + use pyo3::IntoPyObjectExt; + Python::attach(|py| { + let (params, mask) = crate::sql_log::shown_params(py, &statement.binds, secrets)?; + Ok(pyo3::types::PyTuple::new( + py, + [ + statement.sql.as_str().into_bound_py_any(py)?, + params.into_any(), + mask.into_any(), + crate::sql_log::dialect_name(backend).into_bound_py_any(py)?, + ], + )? + .into_any() + .unbind()) + }) +} + +/// Render one query statement for `route` without sending it: resolve the +/// route's engine, take its connection the way the call would but open no +/// transaction of its own (a session's pinned connection, or the open +/// `transaction()`'s, still serves the catalog probe), and run `build`. +/// Only a first-touch catalog probe reaches the database. +macro_rules! render_on_route { + ($route:expr, $secrets:expr, |$engine:ident, $exec:ident, $backend:ident| $build:expr) => {{ + let r = $route.get(); + let (_, engine, tx_conn, $backend) = route_engine(r)?; + let scope = OperationScope::unwrapped(&engine, r.session_id.as_deref(), tx_conn).await?; + let built = { + let $engine: &EngineHandle = &engine; + let $exec = Executor::new(scope.connection(), &engine); + $build.await + }; + let statement = scope.finish(built).await?; + rendered_parts(&statement, &$secrets, $backend) + }}; +} + +/// Render the `SELECT` [`fetch_filtered`] would send for the same +/// arguments, without sending it (`all()` / `first()` `.sql()`). +/// +/// Args: +/// cls (PyAny): The Python model class. +/// query_ir_json (str): The serialized QueryIR envelope JSON. +/// route (RouteHandle): The resolved route. +/// record_cls (PyAny | None): As for `fetch_filtered`. +/// hop_classes (dict[str, type] | None): As for `fetch_filtered`. +/// secret_values (list[object]): The secret-typed literals the query +/// compiled with, masked in the answer. +/// +/// Returns: +/// tuple[str, tuple, tuple[bool, ...], str]: The SQL, the parameters +/// (`None` where masked), the mask and the dialect. +/// +/// # Errors +/// The errors `fetch_filtered` raises before it sends. +#[pyfunction] +#[pyo3(signature = ( + cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() +))] +pub fn render_fetch<'py>( + py: Python<'py>, + cls: Bound<'py, PyAny>, + query_ir_json: String, + route: Py, + record_cls: Option>, + hop_classes: Option>, + secret_values: Vec>, +) -> PyResult> { + let name = crate::state::model_identity(&cls)?; + let (mut plan, request) = fetch_request(&query_ir_json, record_cls, hop_classes)?; + let secrets = operation_secret_values(&secret_values, plan_secret_values(py, &cls, &plan)?)?; + let log = operation_log(py, "fetch", &route.get().connection_name, no_secrets)?; + let rendering = async move { + render_on_route!(route, secrets, |engine, exec, backend| async { + build_fetch( + &mut plan, + &name, + request.include_paths.as_deref(), + request.projected.as_deref(), + engine, + exec, + backend, + ) + .await + .map(|built| built.statement) + }) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, rendering)) +} + +/// Render the `SELECT COUNT(*)` [`count_filtered`] would send for the same +/// arguments, without sending it (`count()` / `exists()` `.sql()`). +/// +/// Args: +/// name (str): Model class name. +/// query_ir_json (str): Serialized Query IR envelope JSON. +/// route (RouteHandle): The resolved route. +/// secret_values (list[object]): The secret-typed literals the query +/// compiled with, masked in the answer. +/// operation (str): `"count"` or `"exists"`, as for `count_filtered`. +/// +/// Returns: +/// tuple[str, tuple, tuple[bool, ...], str]: The SQL, the parameters +/// (`None` where masked), the mask and the dialect. +/// +/// # Errors +/// The errors `count_filtered` raises before it sends. +#[pyfunction] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new(), operation="count"))] +pub fn render_count<'py>( + py: Python<'py>, + name: String, + query_ir_json: String, + route: Py, + secret_values: Vec>, + operation: &str, +) -> PyResult> { + let (mut plan, operation) = count_plan(&query_ir_json, operation)?; + let secrets = operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + )?; + let log = operation_log(py, operation, &route.get().connection_name, no_secrets)?; + let rendering = async move { + render_on_route!(route, secrets, |engine, exec, backend| build_count( + &mut plan, &name, engine, exec, backend + )) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, rendering)) +} + +/// Render the `UPDATE` [`update_filtered`] would send for the same +/// arguments, without sending it (`update()` `.sql()`). +/// +/// Args: +/// name (str): Model class name. +/// query_ir_json (str): Serialized Query IR envelope JSON. +/// route (RouteHandle): The resolved route. +/// secret_values (list[object]): The secret-typed literals the query +/// compiled with, masked in the answer. +/// +/// Returns: +/// tuple[str, tuple, tuple[bool, ...], str]: The SQL, the parameters +/// (`None` where masked), the mask and the dialect. +/// +/// # Errors +/// The errors `update_filtered` raises before it sends. +#[pyfunction] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +pub fn render_update<'py>( + py: Python<'py>, + name: String, + query_ir_json: String, + route: Py, + secret_values: Vec>, +) -> PyResult> { + let mut plan = update_plan(&name, &query_ir_json)?; + let secrets = operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + )?; + let log = operation_log(py, "update", &route.get().connection_name, no_secrets)?; + let rendering = async move { + render_on_route!(route, secrets, |engine, exec, backend| build_update( + &mut plan, &name, engine, exec, backend + )) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, rendering)) +} + +/// Render the `DELETE` [`delete_filtered`] would send for the same +/// arguments, without sending it (`delete()` `.sql()`). +/// +/// Args: +/// name (str): Model class name. +/// query_ir_json (str): Serialized Query IR envelope JSON. +/// route (RouteHandle): The resolved route. +/// secret_values (list[object]): The secret-typed literals the query +/// compiled with, masked in the answer. +/// +/// Returns: +/// tuple[str, tuple, tuple[bool, ...], str]: The SQL, the parameters +/// (`None` where masked), the mask and the dialect. +/// +/// # Errors +/// The errors `delete_filtered` raises before it sends. +#[pyfunction] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +pub fn render_delete<'py>( + py: Python<'py>, + name: String, + query_ir_json: String, + route: Py, + secret_values: Vec>, +) -> PyResult> { + let mut plan = delete_plan(&query_ir_json)?; + let secrets = operation_secret_values( + &secret_values, + plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, + )?; + let log = operation_log(py, "delete", &route.get().connection_name, no_secrets)?; + let rendering = async move { + render_on_route!(route, secrets, |engine, exec, backend| build_delete( + &mut plan, &name, engine, exec, backend + )) + }; + pyo3_async_runtimes::tokio::future_into_py(py, crate::sql_log::scope(log, rendering)) +} + /// Insert many-to-many association rows into a join table. /// /// Args: diff --git a/src/sql_log.rs b/src/sql_log.rs index c38f41da..3c8cde6d 100644 --- a/src/sql_log.rs +++ b/src/sql_log.rs @@ -278,7 +278,35 @@ fn mask_of(binds: &[EngineBindValue], secrets: &[EngineBindValue]) -> Vec binds.iter().map(|bind| secrets.contains(bind)).collect() } -fn dialect_name(dialect: Dialect) -> &'static str { +/// A statement's parameters as a record shows them: each bind as its +/// Python value, `None` where it equals one of `secrets`, beside the mask +/// that marks those positions. The statement log and a rendered statement +/// (`.sql()`) both show parameters through this one function. +/// +/// # Errors +/// The `PyErr` from converting a bind to Python. +pub fn shown_params<'py>( + py: Python<'py>, + binds: &[EngineBindValue], + secrets: &[EngineBindValue], +) -> PyResult<(Bound<'py, PyTuple>, Bound<'py, PyTuple>)> { + let mask = mask_of(binds, secrets); + let params = binds + .iter() + .zip(&mask) + .map(|(bind, &masked)| { + if masked { + Ok(py.None().into_bound(py)) + } else { + bind_to_py(py, bind) + } + }) + .collect::>>()?; + Ok((PyTuple::new(py, params)?, PyTuple::new(py, mask)?)) +} + +/// The name a record gives `dialect`: `"postgres"` or `"sqlite"`. +pub fn dialect_name(dialect: Dialect) -> &'static str { match dialect { Dialect::Postgres => "postgres", Dialect::Sqlite => "sqlite", @@ -314,26 +342,15 @@ fn emit( duration_ms: f64, outcome: Result, &sqlx::Error>, ) -> PyResult<()> { - let mask = mask_of(binds, &context.secret_values); - let params = binds - .iter() - .zip(&mask) - .map(|(bind, &masked)| { - if masked { - Ok(py.None().into_bound(py)) - } else { - bind_to_py(py, bind) - } - }) - .collect::>>()?; + let (params, mask) = shown_params(py, binds, &context.secret_values)?; let (rows, error) = match outcome { Ok(rows) => (rows, None), Err(err) => (None, Some(err.to_string())), }; let record = PyDict::new(py); record.set_item("sql", sql)?; - record.set_item("params", PyTuple::new(py, params)?)?; - record.set_item("mask", PyTuple::new(py, mask)?)?; + record.set_item("params", params)?; + record.set_item("mask", mask)?; record.set_item("dialect", dialect_name(dialect))?; record.set_item("duration_ms", duration_ms)?; record.set_item("operation", context.operation)?; @@ -368,6 +385,23 @@ mod tests { assert_eq!(mask_of(&binds, &[]), vec![false, false, false]); } + #[test] + fn shown_params_puts_none_where_a_bind_is_secret() { + let secret = EngineBindValue::String("hunter2".into()); + let shown = Python::attach(|py| -> PyResult<(String, String)> { + let (params, mask) = + shown_params(py, &[EngineBindValue::I64(7), secret.clone()], &[secret])?; + Ok((params.repr()?.to_string(), mask.repr()?.to_string())) + }); + match shown { + Ok((params, mask)) => { + assert_eq!(params, "(7, None)"); + assert_eq!(mask, "(False, True)"); + } + Err(err) => panic!("shown_params failed: {err}"), + } + } + #[tokio::test] async fn outside_a_scope_there_is_no_context_and_observe_does_nothing() { assert!(current().is_none()); diff --git a/tests/static_fixtures/bad_updates.py b/tests/static_fixtures/bad_updates.py new file mode 100644 index 00000000..a37f25c1 --- /dev/null +++ b/tests/static_fixtures/bad_updates.py @@ -0,0 +1,26 @@ +"""Type-checked (never executed): mixing `update()`'s two forms must FAIL `ty check`. + +`update()` takes a recipe callable or keyword literals, never both, and so +does `update.sql()`, which takes the terminal's own arguments. +test_static_contracts.py asserts this file produces one `no-matching-overload` +diagnostic per misuse. If it starts passing, the overloads have stopped +biting. +""" + +from typing import Annotated + +from ferro import FerroField, Model +from ferro.query import Query + + +class BadUAccount(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + visits: int = 0 + + +async def _mixed_forms_on_the_call() -> None: + await Query(BadUAccount).update(lambda account: {"visits": 1}, visits=1) + + +async def _mixed_forms_on_the_rendering() -> None: + await Query(BadUAccount).update.sql(lambda account: {"visits": 1}, visits=1) diff --git a/tests/static_fixtures/good_updates.py b/tests/static_fixtures/good_updates.py new file mode 100644 index 00000000..29a89853 --- /dev/null +++ b/tests/static_fixtures/good_updates.py @@ -0,0 +1,26 @@ +"""Type-checked (never executed): each of `update()`'s forms must PASS `ty check`. + +The recipe form and the keyword form type-check on the call and on +`update.sql()`, with the call's and the rendering's own return types. +""" + +from typing import Annotated, assert_type + +from ferro import FerroField, Model, RenderedSql +from ferro.query import Query + + +class GoodUAccount(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + visits: int = 0 + + +async def _each_form() -> None: + query = Query(GoodUAccount).where(lambda account: account.id == 1) + assert_type(await query.update(visits=2), int) + assert_type(await query.update(lambda account: {"visits": account.visits + 1}), int) + assert_type(await query.update.sql(visits=2), RenderedSql) + assert_type( + await query.update.sql(lambda account: {"visits": account.visits + 1}), + RenderedSql, + ) diff --git a/tests/test_query_typing.py b/tests/test_query_typing.py index 63c73b1a..0866e483 100644 --- a/tests/test_query_typing.py +++ b/tests/test_query_typing.py @@ -170,3 +170,46 @@ class _StaticUser(Model): # FieldProxy comparisons resolve to QueryNode (the lambda mechanism) assert_type(FieldProxy("archived") == False, QueryNode) # noqa: E712 + + # Every terminal's `.sql()` renders with the terminal's own arguments and + # returns a RenderedSql, through the Relation and ProjectedQuery overrides + # too, while the call keeps its own return shape. + from ferro import RenderedSql, Row, Rows + + class _StaticAuthor(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + posts: Relation[list["_StaticPost"]] = BackRef() + + class _StaticPost(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + author: Annotated[_StaticAuthor, ForeignKey(related_name="posts")] + + async def _rendered_statement_shapes(author: _StaticAuthor) -> None: + query = Query(_StaticUser).where(lambda user: user.archived == False) # noqa: E712 + assert_type(await query.all(), list[_StaticUser]) + assert_type(await query.all.sql(), RenderedSql) + assert_type(await query.first(), _StaticUser | None) + assert_type(await query.first.sql(), RenderedSql) + assert_type(await query.count(), int) + assert_type(await query.count.sql(), RenderedSql) + assert_type(await query.exists.sql(), RenderedSql) + assert_type(await query.update(email="x"), int) + assert_type(await query.update.sql(email="x"), RenderedSql) + assert_type( + await query.update.sql(lambda user: {"email": user.email}), RenderedSql + ) + assert_type(await query.delete.sql(), RenderedSql) + + assert_type(await author.posts.all(), list[_StaticPost]) + assert_type(await author.posts.all.sql(), RenderedSql) + assert_type(await author.posts.first(), _StaticPost | None) + assert_type(await author.posts.first.sql(), RenderedSql) + assert_type(await author.posts.count.sql(), RenderedSql) + + projected = _StaticUser.select(lambda user: user.email) + assert_type(await projected.all(), Rows[Row]) + assert_type(await projected.all.sql(), RenderedSql) + assert_type(await projected.first(), Row | None) + assert_type(await projected.first.sql(), RenderedSql) + assert_type(await projected.count(), int) + assert_type(await projected.count.sql(), RenderedSql) diff --git a/tests/test_rendered_statement.py b/tests/test_rendered_statement.py new file mode 100644 index 00000000..58c25d26 --- /dev/null +++ b/tests/test_rendered_statement.py @@ -0,0 +1,369 @@ +"""The rendered statement: every `Query` terminal's `.sql()` (ADR-0057). + +```python +query = RsAccount.where(lambda account: account.visits >= 18) +rendered = await query.all.sql() +rendered.sql # 'SELECT ... WHERE "rsaccount"."visits" >= $1' +rendered.params # (18,) +rendered.dialect # 'postgres' +``` + +`.sql()` returns what the call would send without sending it: the same SQL +and parameters the statement log records for the call, built by the same +engine function, for the database the call would run on, with secrets shown +as `REDACTED`. The parity pin below holds that for every terminal on both +dialects: the rendered statement equals the `ferro.sql` record the executed +call writes. +""" + +import logging +from collections.abc import Awaitable, Callable +from typing import Annotated, Any + +import pytest +from pydantic import SecretStr + +import ferro +from ferro import ( + REDACTED, + BackRef, + Model, + Relation, + RenderedSql, + engines, +) +from ferro._core import identity_map_len +from ferro.base import FerroField, ForeignKey + +pytestmark = pytest.mark.backend_matrix + + +class RsAccount(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + email: Annotated[str, FerroField(unique=True)] + token: SecretStr + visits: int = 0 + notes: Relation[list["RsNote"]] = BackRef() + + +class RsNote(Model): + id: Annotated[int | None, FerroField(primary_key=True)] = None + label: str + account: Annotated[RsAccount | None, ForeignKey(related_name="notes")] = None + + +async def _seeded(db_url: str) -> RsAccount: + """Connect, and save one account with one note.""" + await ferro.connect(db_url, auto_migrate=True) + async with engines.session(): + ada = RsAccount( + id=1, email="ada@example.com", token=SecretStr("sk_live_1"), visits=3 + ) + await ada.save() + await RsNote(id=1, label="hello", account=ada).save() + return ada + + +def _sent(records: list[logging.LogRecord]) -> list[logging.LogRecord]: + """The records of the statements the call itself sent: everything but the + pass `connect` runs and the catalog probe of a table's first touch.""" + return [r for r in records if r.operation not in ("migrate", "catalog")] + + +def _sentinel_positions(params: tuple[object, ...]) -> list[int]: + return [i for i, value in enumerate(params) if value is REDACTED] + + +# Each case: (name, the terminal to render and call, its arguments, whether a +# parameter is a secret). The terminal is read from a fresh query each time. +Terminal = Callable[[RsAccount], Any] +CASES: list[tuple[str, Terminal, tuple[Any, ...], dict[str, Any], bool]] = [ + ( + "all-secret-predicate", + lambda ada: RsAccount.where(lambda account: account.token == "sk_live_1").all, + (), + {}, + True, + ), + ( + "all-include", + lambda ada: ( + RsNote.select() + .include(lambda note: note.account) + .where(lambda note: note.label == "hello") + .order_by(lambda note: note.id) + .all + ), + (), + {}, + False, + ), + ( + "first", + lambda ada: ( + RsAccount.where(lambda account: account.visits >= 1) + .order_by(lambda account: account.id) + .first + ), + (), + {}, + False, + ), + ( + "count-traversed-secret", + lambda ada: RsNote.where(lambda note: note.account.token == "sk_live_1").count, + (), + {}, + True, + ), + ( + "exists", + lambda ada: ( + RsAccount.where(lambda account: account.email == "ada@example.com").exists + ), + (), + {}, + False, + ), + ( + "update-fields-secret", + lambda ada: RsAccount.where(lambda account: account.id == 1).update, + (), + {"token": SecretStr("sk_live_2")}, + True, + ), + ( + "update-recipe", + lambda ada: RsAccount.where(lambda account: account.id == 1).update, + (lambda account: {"visits": account.visits + 1},), + {}, + False, + ), + ( + "delete-secret", + lambda ada: ( + RsAccount.where(lambda account: account.token == "sk_live_1").delete + ), + (), + {}, + True, + ), + ( + "projected-all", + lambda ada: ( + RsAccount.select(lambda account: account.email) + .where(lambda account: account.visits >= 1) + .all + ), + (), + {}, + False, + ), + ( + "projected-count", + lambda ada: ( + RsAccount.select(lambda account: account.email) + .where(lambda account: account.token == "sk_live_1") + .count + ), + (), + {}, + True, + ), + ("relation-all", lambda ada: ada.notes.all, (), {}, False), + ("relation-first", lambda ada: ada.notes.first, (), {}, False), +] + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + ("terminal", "args", "kwargs", "secret"), + [case[1:] for case in CASES], + ids=[case[0] for case in CASES], +) +async def test_the_rendered_statement_is_the_logged_statement_of_the_call( + db_url, db_backend, statement_records, terminal, args, kwargs, secret +): + """The parity pin: `.sql()` equals the call's `ferro.sql` record in + `sql`, `params` (the `REDACTED` sentinel included) and `dialect`.""" + ada = await _seeded(db_url) + async with engines.session(): + rendered = await terminal(ada).sql(*args, **kwargs) + statement_records.clear() + await terminal(ada)(*args, **kwargs) + + (record,) = _sent(statement_records) + assert isinstance(rendered, RenderedSql) + assert rendered.sql == record.sql + assert rendered.params == record.params + assert _sentinel_positions(rendered.params) == _sentinel_positions(record.params) + assert rendered.dialect == record.dialect == db_backend + assert bool(_sentinel_positions(rendered.params)) is secret + assert "sk_live" not in repr(rendered.params) + + +@pytest.mark.asyncio +async def test_a_rendered_statement_prints_as_its_sql(db_url, db_backend): + await _seeded(db_url) + async with engines.session(): + rendered = await RsAccount.where(lambda account: account.visits >= 18).all.sql() + + placeholder = "$1" if db_backend == "postgres" else "?" + assert str(rendered) == rendered.sql + assert rendered.sql.startswith("SELECT ") + assert f'"rsaccount"."visits" >= {placeholder}' in rendered.sql + assert rendered.params == (18,) + assert rendered.dialect == db_backend + + +def test_a_rendered_statement_is_frozen(): + rendered = RenderedSql(sql="SELECT 1", params=(), dialect="sqlite") + with pytest.raises(AttributeError): + rendered.sql = "SELECT 2" # type: ignore[misc] # ty: ignore[invalid-assignment] + + +@pytest.mark.asyncio +async def test_update_sql_takes_both_forms_and_renders_them_differently(db_url): + await _seeded(db_url) + query = RsAccount.where(lambda account: account.id == 1) + async with engines.session(): + fields = await query.update.sql(visits=19) + recipe = await query.update.sql(lambda account: {"visits": account.visits + 1}) + + assert fields.sql.startswith("UPDATE ") + assert fields.params == (19, 1) + assert recipe.sql.startswith("UPDATE ") + assert recipe.params != fields.params + + +@pytest.mark.asyncio +async def test_first_sql_renders_the_limit_one_statement(db_url): + await _seeded(db_url) + async with engines.session(): + first = await RsAccount.where(lambda account: account.id == 1).first.sql() + every = await RsAccount.where(lambda account: account.id == 1).all.sql() + + assert "LIMIT" in first.sql + assert "LIMIT" not in every.sql + + +@pytest.mark.asyncio +@pytest.mark.parametrize("verb", ["update", "delete"]) +async def test_rendering_a_mutation_changes_no_row_and_sends_only_a_catalog_probe( + db_url, db_backend, statement_records, verb +): + await _seeded(db_url) + statement_records.clear() + async with engines.session() as session: + query = RsAccount.where(lambda account: account.id == 1) + if verb == "update": + await query.update.sql(visits=99) + else: + await query.delete.sql() + sent = list(statement_records) + assert identity_map_len(session.session_id) == 0 + statement_records.clear() + rows = await RsAccount.where(lambda account: account.id == 1).all() + + # Seeding already touched the table, so its catalog is cached. + assert sent == [] + assert [(row.id, row.visits) for row in rows] == [(1, 3)] + + +@pytest.mark.asyncio +@pytest.mark.postgres_only +async def test_rendering_on_a_tables_first_touch_sends_only_the_catalog_probe( + db_url, statement_records +): + """The casts in a rendered statement are the ones the call would use, so + on a table's first touch rendering reads its catalog: one `catalog` + record, and no record of the statement itself.""" + await ferro.connect(db_url, auto_migrate=True) + statement_records.clear() + async with engines.session(): + rendered = await RsAccount.where(lambda account: account.id == 1).delete.sql() + first = [record.operation for record in statement_records] + statement_records.clear() + again = await RsAccount.where(lambda account: account.id == 1).delete.sql() + + assert first == ["catalog"] + assert statement_records == [] + assert again == rendered + + +@pytest.mark.asyncio +async def test_rendering_a_fetch_puts_nothing_in_the_identity_map(db_url): + await _seeded(db_url) + async with engines.session() as session: + await RsAccount.where(lambda account: account.id == 1).all.sql() + await RsAccount.where(lambda account: account.id == 1).first.sql() + assert identity_map_len(session.session_id) == 0 + + +TERMINALS: list[tuple[str, Callable[[], Awaitable[Any]]]] = [ + ("all", lambda: RsAccount.where(lambda account: account.id == 1).all.sql()), + ("first", lambda: RsAccount.where(lambda account: account.id == 1).first.sql()), + ("count", lambda: RsAccount.where(lambda account: account.id == 1).count.sql()), + ("exists", lambda: RsAccount.where(lambda account: account.id == 1).exists.sql()), + ( + "update", + lambda: RsAccount.where(lambda account: account.id == 1).update.sql(visits=2), + ), + ("delete", lambda: RsAccount.where(lambda account: account.id == 1).delete.sql()), +] + + +@pytest.mark.asyncio +@pytest.mark.parametrize( + "render", [t[1] for t in TERMINALS], ids=[t[0] for t in TERMINALS] +) +async def test_rendering_outside_a_session_raises_the_no_route_error(db_url, render): + await _seeded(db_url) + with pytest.raises(RuntimeError, match="No database route for this operation"): + await render() + + +@pytest.mark.asyncio +async def test_update_sql_refuses_mixed_forms_like_update(db_url): + await _seeded(db_url) + query = RsAccount.where(lambda account: account.id == 1) + async with engines.session(): + with pytest.raises( + TypeError, match="either a recipe callable or keyword" + ) as call: + await query.update(lambda account: {"visits": 1}, visits=1) + with pytest.raises( + TypeError, match="either a recipe callable or keyword" + ) as render: + await query.update.sql(lambda account: {"visits": 1}, visits=1) + assert str(call.value) == str(render.value) + + +@pytest.mark.asyncio +@pytest.mark.postgres_only +async def test_using_and_session_route_the_rendering_to_their_database( + db_url, tmp_path +): + """`using=` and `session=` pick the database: the default is SQLite, + `pg` is Postgres, and each rendering speaks its route's dialect.""" + await ferro.connect(f"sqlite:{tmp_path / 'app.db'}?mode=rwc", default=True) + await ferro.create_tables() + await ferro.connect(db_url, name="pg", auto_migrate=True) + + async with engines.session(): + local = await RsAccount.where(lambda account: account.id == 1).all.sql() + async with engines.session("pg"): + by_using = await ( + RsAccount.using("pg").where(lambda account: account.id == 1).all.sql() + ) + async with engines.session("pg") as pg: + async with engines.session(): + by_session = await RsAccount.where( + lambda account: account.id == 1, session=pg + ).count.sql() + + assert (local.dialect, local.params) == ("sqlite", (1,)) + assert "?" in local.sql + assert (by_using.dialect, by_using.params) == ("postgres", (1,)) + assert "$1" in by_using.sql + assert (by_session.dialect, by_session.params) == ("postgres", (1,)) diff --git a/tests/test_static_contracts.py b/tests/test_static_contracts.py index fc7d1fa7..5a90135a 100644 --- a/tests/test_static_contracts.py +++ b/tests/test_static_contracts.py @@ -45,6 +45,27 @@ def test_mutating_query_methods_cannot_carry_pagination(): assert "compile_query" in called, ( f"Query.{method_name}() must build its payload via compile_query" ) + # `.sql()` runs this same body with the send swapped for its render + # twin, so the contract above covers `update.sql` / `delete.sql` too. + decorators = { + dec.id for dec in method.decorator_list if isinstance(dec, ast.Name) + } + # `update` is `_update_terminal`: `terminal` at runtime, its two forms + # overloaded for the type checker. + assert decorators & {"terminal", "_update_terminal"}, ( + f"Query.{method_name} must be a @terminal so .sql() shares its body" + ) + sends = [ + tuple(arg.id for arg in node.args if isinstance(arg, ast.Name)) + for node in ast.walk(method) + if isinstance(node, ast.Call) + and isinstance(node.func, ast.Name) + and node.func.id == "send" + ] + assert sends == [(f"{method_name}_filtered", f"render_{method_name}")], ( + f"Query.{method_name}() must send through " + f"send({method_name}_filtered, render_{method_name})" + ) def _models_module_tree() -> ast.Module: @@ -214,6 +235,26 @@ def test_projected_shape_misuse_fails_the_type_checker(): ) +def test_each_update_form_passes_the_type_checker(): + """The recipe form and the keyword form each type-check, on `update()` + and on `update.sql()`.""" + result = _run_ty(FIXTURES / "good_updates.py") + assert result.returncode == 0, ( + f"update() forms must type-check cleanly:\n{result.stdout}\n{result.stderr}" + ) + + +def test_mixing_update_forms_fails_the_type_checker(): + """A recipe and keyword literals together is a static error on + `update()` and on `update.sql()`, not only the runtime `TypeError`.""" + result = _run_ty(FIXTURES / "bad_updates.py") + assert result.returncode != 0, "bad_updates.py must fail ty" + assert result.stdout.count("no-matching-overload") == 2, ( + "the mixed form on update() and on update.sql() must each be a " + f"static error:\n{result.stdout}" + ) + + def test_include_misuse_fails_the_type_checker(): """include() on a projected query (the `self: Never` pin, #287) and a string include selector are static errors at the call site.""" From 8fe1815a90e38c018f6f6d1e103d6f04a0b97663 Mon Sep 17 00:00:00 2001 From: 0x54 Date: Wed, 21 Oct 2026 08:29:04 -0400 Subject: [PATCH 4/5] =?UTF-8?q?fix(log):=20panel=20round=201=20for=20#765/?= =?UTF-8?q?#766=20=E2=80=94=20keyset=20redaction,=20hashed=20secret=20set,?= =?UTF-8?q?=20one=20log-off=20seam=20(#772)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Panel findings F1, F2, F4, F5, F7 and F11 on PR #771: a plain keyset position on a secret order key (root or traversed) is redacted in the log and in .sql(); the secret-value set is a hashed SecretValues with the mask computed before the GIL; one collector (secret_values_in) and the engine as the only reader of the log switch; one query_secret_values for the four query entries and their render twins; ADR-0057 amended to the value-set rule. Interfaces changed: the secret_values FFI keyword accepts any iterable; secret_values_of/secret_values replaced by secret_values_in, deferred_secret_values, field_values in _bind_payload. Part of #700 (panel round 1 on PR #771) Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP --- ...h-the-statement-log-and-a-terminals-sql.md | 2 + src/ferro/_bind_payload.py | 63 +++-- src/ferro/_core.pyi | 30 +-- src/ferro/models.py | 20 +- src/ferro/query/builder.py | 10 +- src/ferro/query/wire.py | 44 ++-- src/ferro/raw.py | 27 +- src/operations.rs | 249 ++++++++++-------- src/sql_log.rs | 197 ++++++++++++-- tests/test_rendered_statement.py | 39 +++ tests/test_statement_log.py | 158 +++++++++-- 11 files changed, 572 insertions(+), 267 deletions(-) diff --git a/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md b/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md index 7509713f..67a7f2e3 100644 --- a/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md +++ b/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md @@ -35,4 +35,6 @@ On Postgres the SQL text depends on the live table: ferro casts bound values (`$ A bound value shows as `***`, a sentinel whose `repr` is `***` so a test can tell it from the string, when it is a `SecretStr`/`SecretBytes` or when it is bound to a column whose field is declared one. Either rule alone leaks: a plain `"hunter2"` compared against a secret column, or a `SecretStr` passed to `raw.execute` where no column is known. The mask is decided in Python, from the model's declared secret fields and the value's type, and travels to Rust beside the binds; Rust never re-derives it, the one-decision pattern I-1 uses. `.sql()`'s `params` are redacted the same way: one rule, applied in one place, and `print(rendered)` in a bug report is the common use. `SET LOCAL` takes no bind parameters on Postgres, so a session setting's value appears inline, unredacted; settings are tenancy scope, not secrets by declaration. Depends on #760, which makes a secret field store its raw value and hydrate as a secret type. +Amended 2026-10-21 (panel F11 on #771): the mask is a set of values, not a positional flag. The binds are made by the query builder in Rust and never pass through Python one by one, so Python cannot mark positions. Instead each operation has one *secret-value set*, built from two facts. Python collects what every `SecretStr` / `SecretBytes` it unwraps hides (a query's literals as it compiles, a write's field values, a raw statement's arguments) through one collector. Rust adds every value the operation binds to a column whose field is declared secret: predicate literals, literal `SET`s, keyset positions (`after` / `before`) on a secret order key, root or traversed, and a write's secret-column values. A bind is masked when it equals a member of the set, one hash lookup per bind, decided before the GIL is taken to write the record. So `Account.where(lambda account: account.token == "sk_live_1")` logs `params=(***,)` though `"sk_live_1"` is a plain `str`. A plain parameter that happens to equal a secret of the same operation is masked too (`bulk_create` of one row whose email equals another row's token shows both as `***`): over-redaction, in the safe direction, never a leak. The switch is still read once per operation, by the engine at the operation's entry. A write's or raw statement's Python-collected values reach the engine as a lazy iterable it reads only when the log is on; a query's are collected as it compiles, because its `.sql()` masks with the same values. + A pin holds the two doors together: for every terminal on both dialects, `.sql()` equals the record the executed call wrote. diff --git a/src/ferro/_bind_payload.py b/src/ferro/_bind_payload.py index 488610b2..95b49e98 100644 --- a/src/ferro/_bind_payload.py +++ b/src/ferro/_bind_payload.py @@ -10,6 +10,7 @@ import json import uuid +from collections.abc import Iterable, Iterator from datetime import date, datetime, time from decimal import Decimal from enum import Enum @@ -41,39 +42,61 @@ def unwrap_secret(value: Any) -> Any: return value -def secret_values_of(fields: Mapping[str, object]) -> tuple[object, ...]: - """Return what each `SecretStr` / `SecretBytes` among `fields`' values hides. +def secret_values_in(values: Iterable[object]) -> tuple[object, ...]: + """Return what each `SecretStr` / `SecretBytes` among `values` hides. - The statement log masks a bound parameter equal to any of these, so a - secret written through this mapping never reaches a record. + The one collector of an operation's secret values: a query's compile, a + write and a raw statement each call it once. The statement log and a + rendered statement mask a bound parameter equal to any of these. Args: - fields: Field or column names mapped to the values about to be bound. + values: The values about to be bound. A list, tuple or set among them + is searched too, so a secret inside an `IN` list is found. Returns: - The unwrapped value of every secret in `fields`, in order; empty when + The unwrapped value of every secret in `values`, in order; empty when there is none. """ - return tuple( - unwrap_secret(value) - for value in fields.values() - if isinstance(value, (SecretStr, SecretBytes)) - ) + found: list[object] = [] + pending = list(values) + pending.reverse() + while pending: + value = pending.pop() + if isinstance(value, (SecretStr, SecretBytes)): + found.append(unwrap_secret(value)) + elif isinstance(value, (list, tuple, set, frozenset)): + pending.extend(reversed(list(value))) + return tuple(found) -def secret_values(instance: Any) -> tuple[object, ...]: - """Return what each secret field of a model instance hides. +def deferred_secret_values(values: Iterable[object]) -> Iterator[object]: + """Yield the secret values in `values`, collected on first read. + + A write or a raw statement hands this to the engine, which reads it only + when the statement log is on: the engine's one read of the log's switch + decides whether anything is collected. Args: - instance: The model instance about to be saved. + values: The values about to be bound, read lazily. - Returns: - The unwrapped value of every field holding a `SecretStr` or - `SecretBytes`, in field order; empty when there is none. + Yields: + The unwrapped value of every secret in `values`, in order. + """ + yield from secret_values_in(values) + + +def field_values(instances: Iterable[Any]) -> Iterator[object]: + """Yield every field value of each model instance, in field order. + + Args: + instances: The model instances about to be saved. + + Yields: + Each instance's field values, as the instance holds them. """ - return secret_values_of( - {name: getattr(instance, name, None) for name in type(instance).model_fields} - ) + for instance in instances: + for name in type(instance).model_fields: + yield getattr(instance, name, None) def _raw_bound_fields(instance: Any) -> dict[str, Any]: diff --git a/src/ferro/_core.pyi b/src/ferro/_core.pyi index e1b2251b..318524f0 100644 --- a/src/ferro/_core.pyi +++ b/src/ferro/_core.pyi @@ -1,4 +1,4 @@ -from collections.abc import Callable +from collections.abc import Callable, Iterable from pathlib import Path from typing import Any, Literal, Optional @@ -651,14 +651,14 @@ async def fetch_filtered( record_cls: type | None = None, hop_classes: dict[str, type] | None = None, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> list[Any]: ... async def count_filtered( name: str, query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., operation: Literal["count", "exists"] = "count", ) -> int: ... async def fetch_one( @@ -672,21 +672,21 @@ async def save_record( route: RouteHandle, mode: str = "insert", *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int | None: ... async def update_record( name: str, data: dict[str, Any], route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int: ... async def save_bulk_records( name: str, rows: list[dict[str, Any]], route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int: ... async def delete_record( name: str, @@ -698,14 +698,14 @@ async def delete_filtered( query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int: ... async def update_filtered( name: str, query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int: ... RenderedParts = tuple[str, tuple[object, ...], tuple[bool, ...], str] @@ -719,14 +719,14 @@ async def render_fetch( record_cls: type | None = None, hop_classes: dict[str, type] | None = None, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> RenderedParts: ... async def render_count( name: str, query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., operation: Literal["count", "exists"] = "count", ) -> RenderedParts: ... async def render_update( @@ -734,14 +734,14 @@ async def render_update( query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> RenderedParts: ... async def render_delete( name: str, query_ir_json: str, route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> RenderedParts: ... async def add_m2m_links( join_table: str, @@ -791,21 +791,21 @@ async def raw_execute( route: RouteHandle, autocommit: bool = False, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> int: ... async def raw_fetch_all( sql: str, args: list[Any], route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> list[dict[str, Any]]: ... async def raw_fetch_one( sql: str, args: list[Any], route: RouteHandle, *, - secret_values: list[object] = ..., + secret_values: Iterable[object] = ..., ) -> dict[str, Any] | None: ... def register_instance( name: str, diff --git a/src/ferro/models.py b/src/ferro/models.py index 3f245b08..1fc5f228 100644 --- a/src/ferro/models.py +++ b/src/ferro/models.py @@ -1,6 +1,5 @@ """Define the core ORM model base and transaction helpers for Ferro.""" -import logging from contextlib import asynccontextmanager from enum import Enum from typing import ( @@ -25,11 +24,11 @@ from ._bind_payload import ( apply_save_exclude, apply_save_only, + deferred_secret_values, + field_values, normalize_save_columns, save_bind_payload, - secret_values, ) -from ._sql_log import LOGGER as _SQL_LOG from ._core import ( begin_transaction, commit_transaction, @@ -58,17 +57,6 @@ ) -def _secrets_to_mask(instances: "list[Model]") -> list[object]: - """The secret field values of `instances` the statement log must mask. - - Collected only while `ferro.sql` is enabled for `DEBUG`: with the log off - no record is written, so there is nothing to mask. - """ - if not _SQL_LOG.isEnabledFor(logging.DEBUG): - return [] - return [value for instance in instances for value in secret_values(instance)] - - _FERRO_CONNECTION_ATTR = "__ferro_connection_name" _FERRO_PERSISTED_ATTR = "__ferro_persisted" @@ -474,7 +462,7 @@ async def save( "Use Query.update() for set-oriented or expression writes." ) route, identity_using = await _instance_transaction_route(self, using, session) - secrets = _secrets_to_mask([self]) + secrets = deferred_secret_values(field_values([self])) new_id = None if on_conflict == "update": new_id = await save_record( @@ -827,7 +815,7 @@ async def bulk_create( cls.__ferro_identity__, data, route, - secret_values=_secrets_to_mask(list(instances)), + secret_values=deferred_secret_values(field_values(instances)), ) @classmethod diff --git a/src/ferro/query/builder.py b/src/ferro/query/builder.py index 6ac11d6f..a628a6c4 100644 --- a/src/ferro/query/builder.py +++ b/src/ferro/query/builder.py @@ -1305,7 +1305,7 @@ async def all(self: "Query[T]") -> list[T]: compiled.wire_json, route, hop_classes=compiled.hop_classes, - secret_values=list(compiled.secret_values), + secret_values=compiled.secret_values, ) if self._before is not None: rows.reverse() @@ -1333,7 +1333,7 @@ async def _count(self, operation: Literal["count", "exists"]) -> int: model_identity(self.model_cls), compiled.wire_json, route, - secret_values=list(compiled.secret_values), + secret_values=compiled.secret_values, operation=operation, ) @@ -1401,7 +1401,7 @@ async def update( model_identity(self.model_cls), compiled.wire_json, route, - secret_values=list(compiled.secret_values), + secret_values=compiled.secret_values, ) @terminal @@ -1445,7 +1445,7 @@ async def delete(self: "Query[T]") -> int: model_identity(self.model_cls), compiled.wire_json, route, - secret_values=list(compiled.secret_values), + secret_values=compiled.secret_values, ) @terminal @@ -1881,7 +1881,7 @@ async def all(self: "ProjectedQuery[T]") -> Rows[Row]: # type: ignore[override] route, record_cls=Row, hop_classes=compiled.hop_classes, - secret_values=list(compiled.secret_values), + secret_values=compiled.secret_values, ) if self._before is not None: records.reverse() diff --git a/src/ferro/query/wire.py b/src/ferro/query/wire.py index d3466868..0c820f7c 100644 --- a/src/ferro/query/wire.py +++ b/src/ferro/query/wire.py @@ -25,12 +25,9 @@ from dataclasses import dataclass, field from typing import TYPE_CHECKING, Any, Literal, Mapping -from pydantic import SecretBytes, SecretStr - +from .. import _bind_payload from .._bind_payload import ( canonicalize_wire_scalar, - secret_values_of, - unwrap_secret, update_bind_payload, ) from ..state import resolve_compile_connection_name @@ -947,29 +944,20 @@ class — an ``instances`` plan (#286) or a ``record`` plan with traversed masks a bound parameter equal to any of these.""" -def _collect_secret_literals(value: Any, out: list[object]) -> None: - """Append what each secret in one literal hides, reaching into lists.""" - if isinstance(value, (SecretStr, SecretBytes)): - out.append(unwrap_secret(value)) - elif isinstance(value, (list, tuple, set, frozenset)): - for item in value: - _collect_secret_literals(item, out) - - -def _collect_node_secrets(node: QueryNode, out: list[object]) -> None: - """Append the secret literals of one predicate tree, depth first.""" +def _collect_node_literals(node: QueryNode, out: list[object]) -> None: + """Append the literals of one predicate tree, depth first.""" if node.child is not None: - _collect_node_secrets(node.child, out) + _collect_node_literals(node.child, out) elif node.exists is not None: for inner in node.exists.where: - _collect_node_secrets(inner, out) + _collect_node_literals(inner, out) elif node.is_compound: if node.left is not None: - _collect_node_secrets(node.left, out) + _collect_node_literals(node.left, out) if node.right is not None: - _collect_node_secrets(node.right, out) + _collect_node_literals(node.right, out) else: - _collect_secret_literals(node.value, out) + out.append(node.value) def _secret_literals( @@ -982,19 +970,19 @@ def _secret_literals( Read from the same values the payload compiles from (predicate literals, the SET values of an update, a fetch's position bounds), so the set and - the wire cannot disagree about which literals were secrets. + the wire cannot disagree about which literals were secrets, and collected + in one call to the one collector. """ - out: list[object] = [] + literals: list[object] = [] for node in query.where_clause: - _collect_node_secrets(node, out) + _collect_node_literals(node, literals) if verb == "update": - out.extend( - secret_values_of(recipe if recipe is not None else assignments or {}) - ) + sets = recipe if recipe is not None else assignments or {} + literals.extend(sets.values()) if verb == "fetch": for bound in (query._after, query._before): - _collect_secret_literals(bound or (), out) - return tuple(out) + literals.extend(bound or ()) + return _bind_payload.secret_values_in(literals) def _payload_hop_classes(payload: QueryIrPayload) -> dict[str, type] | None: diff --git a/src/ferro/raw.py b/src/ferro/raw.py index 7f5f3e0c..92d57e93 100644 --- a/src/ferro/raw.py +++ b/src/ferro/raw.py @@ -25,16 +25,14 @@ import decimal import enum import json -import logging import uuid from typing import Any -from ._bind_payload import secret_values_of, unwrap_secret +from ._bind_payload import deferred_secret_values, unwrap_secret from ._core import RouteHandle from ._core import raw_execute as _raw_execute from ._core import raw_fetch_all as _raw_fetch_all from ._core import raw_fetch_one as _raw_fetch_one -from ._sql_log import LOGGER as _SQL_LOG from .state import resolve_operation_scope __all__ = ["execute", "fetch_all", "fetch_one", "Transaction"] @@ -68,17 +66,6 @@ def _marshal(val: Any) -> bool | int | float | str | bytes | None: ) -def _secrets_to_mask(args: tuple[Any, ...]) -> list[object]: - """The secret arguments the statement log must mask, unwrapped. - - Collected only while `ferro.sql` is enabled for `DEBUG`: with the log off - no record is written, so there is nothing to mask. - """ - if not _SQL_LOG.isEnabledFor(logging.DEBUG): - return [] - return list(secret_values_of({str(index): arg for index, arg in enumerate(args)})) - - def _check_sql(sql: str) -> None: if not isinstance(sql, str) or not sql.strip(): raise ValueError("sql must be a non-empty statement") @@ -130,7 +117,7 @@ async def execute( marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) return await _raw_execute( - sql, marshalled, route, autocommit, secret_values=_secrets_to_mask(args) + sql, marshalled, route, autocommit, secret_values=deferred_secret_values(args) ) @@ -146,7 +133,7 @@ async def fetch_all( marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) return await _raw_fetch_all( - sql, marshalled, route, secret_values=_secrets_to_mask(args) + sql, marshalled, route, secret_values=deferred_secret_values(args) ) @@ -161,7 +148,7 @@ async def fetch_one( marshalled = [_marshal(a) for a in args] route = _transaction_or_using(using, session) return await _raw_fetch_one( - sql, marshalled, route, secret_values=_secrets_to_mask(args) + sql, marshalled, route, secret_values=deferred_secret_values(args) ) @@ -188,19 +175,19 @@ async def execute(self, sql: str, *args: Any) -> int: _check_sql(sql) marshalled = [_marshal(a) for a in args] return await _raw_execute( - sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + sql, marshalled, self._route, secret_values=deferred_secret_values(args) ) async def fetch_all(self, sql: str, *args: Any) -> list[dict[str, Any]]: _check_sql(sql) marshalled = [_marshal(a) for a in args] return await _raw_fetch_all( - sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + sql, marshalled, self._route, secret_values=deferred_secret_values(args) ) async def fetch_one(self, sql: str, *args: Any) -> dict[str, Any] | None: _check_sql(sql) marshalled = [_marshal(a) for a in args] return await _raw_fetch_one( - sql, marshalled, self._route, secret_values=_secrets_to_mask(args) + sql, marshalled, self._route, secret_values=deferred_secret_values(args) ) diff --git a/src/operations.rs b/src/operations.rs index c94b459d..479b599a 100644 --- a/src/operations.rs +++ b/src/operations.rs @@ -13,6 +13,7 @@ use crate::session_settings::{ hold_pinned_connection, merge_setting, pinned_session, release_pinned_connection, settings_changed, }; +use crate::sql_log::SecretValues; use crate::state::{ ConnectionSlot, Dialect, TRANSACTION_REGISTRY, TransactionConnection, TransactionHandle, connection_for_route, engine_for_connection, ensure_session_idle_for_close, register_session, @@ -1401,9 +1402,11 @@ impl BuiltStatement { } /// The statement-log context an operation entry opens (ADR-0057), or `None` -/// when `ferro.sql` is not enabled for `DEBUG`. Asked once, while the entry -/// holds the GIL; `secret_values` is called only when the log is on, so an -/// operation with the log off builds no secret-value set. +/// when `ferro.sql` is not enabled for `DEBUG`. This is the operation's one +/// read of the switch, made while the entry holds the GIL; `secret_values` +/// is called only when the log is on, so an operation with the log off +/// builds no secret-value set and, when Python hands its values over as a +/// lazy iterable, collects none. /// /// # Errors /// The `PyErr` from asking the logger, or from `secret_values`. @@ -1414,26 +1417,40 @@ fn operation_log( secret_values: F, ) -> PyResult> where - F: FnOnce(Python<'_>) -> PyResult>, + F: FnOnce(Python<'_>) -> PyResult, { if !crate::sql_log::enabled(py)? { return Ok(None); } let mut context = crate::sql_log::StatementContext::new(operation, connection); - context.secret_values = secret_values(py)?; + context.secret_values = std::sync::Arc::new(secret_values(py)?); Ok(Some(context)) } /// No secret values: an operation that binds none (a primary key, link ids, /// transaction control). -fn no_secrets(_py: Python<'_>) -> PyResult> { - Ok(Vec::new()) +fn no_secrets(_py: Python<'_>) -> PyResult { + Ok(SecretValues::default()) } -/// The binds the secret values Python collected make, through the same -/// conversion a raw bind takes (a secret is a `str` or `bytes`). -fn secret_binds_from_py(values: &[Bound<'_, PyAny>]) -> PyResult> { - values.iter().map(python_to_engine_bind_value).collect() +/// Add to `out` the secret values Python collected (any iterable, `None` for +/// none), each through the conversion a raw bind takes (a secret is a `str` +/// or `bytes`). Iterating is what runs a lazy Python collector. +fn secret_binds_from_py(values: Option<&Bound<'_, PyAny>>, out: &mut SecretValues) -> PyResult<()> { + if let Some(values) = values { + for value in values.try_iter()? { + out.insert(python_to_engine_bind_value(&value?)?); + } + } + Ok(()) +} + +/// The secret-value set Python handed over, and nothing else: a raw +/// statement, whose binds no column names. +fn python_secret_values(values: Option<&Bound<'_, PyAny>>) -> PyResult { + let mut out = SecretValues::default(); + secret_binds_from_py(values, &mut out)?; + Ok(out) } /// The model classes the Python registry holds, keyed by identity. @@ -1541,7 +1558,7 @@ fn collect_secret_leaf_binds( scope_table: &str, joins: &[ferro_schema_ir::QueryJoin], secret: &mut SecretColumns<'_>, - out: &mut Vec, + out: &mut SecretValues, ) -> PyResult<()> { use ferro_schema_ir::QueryNode; match node { @@ -1578,11 +1595,13 @@ fn collect_secret_leaf_binds( Ok(()) } -/// The values a query binds to secret columns: every predicate literal -/// compared against a column whose field the model (or a traversed hop's -/// model) declares `SecretStr` / `SecretBytes`, and every literal `SET` of -/// one. Added to the operation's secret-value set, beside the secret-typed -/// literals Python collected. +/// Add to `out` the values a query binds to secret columns: every +/// predicate literal compared against a column whose field the model (or a +/// traversed hop's model) declares `SecretStr` / `SecretBytes`, every +/// literal `SET` of one, and every keyset position (`after` / `before`) +/// value bound against a secret order key, root or traversed. A `SET` +/// expression (`+`, `-`, `merge`) never targets a secret column: it takes a +/// numeric or JSON column only. /// /// # Errors /// The `PyErr` from resolving a hop's model class or reading its converter @@ -1591,59 +1610,83 @@ fn plan_secret_values( py: Python<'_>, root_cls: &Bound<'_, PyAny>, plan: &QueryPlan, -) -> PyResult> { + out: &mut SecretValues, +) -> PyResult<()> { let identity = crate::state::model_identity(root_cls)?; let root_table = crate::state::registered_model(&identity)? .table_name .clone(); let mut secret = SecretColumns::new(py, &root_table, root_cls)?; - let mut out = Vec::new(); for node in &plan.where_clause { - collect_secret_leaf_binds(node, &root_table, &plan.joins, &mut secret, &mut out)?; + collect_secret_leaf_binds(node, &root_table, &plan.joins, &mut secret, out)?; } for assignment in &plan.set_assignments { if let QueryValueExpr::Literal { value } = &assignment.value && secret.contains(&root_table, &assignment.column)? { - crate::sql_log::literal_secret_binds(&value.kind, &value.value, &mut out); + crate::sql_log::literal_secret_binds(&value.kind, &value.value, out); + } + } + for position in [&plan.after, &plan.before].into_iter().flatten() { + for (order, value) in plan.order_by.iter().zip(position) { + let table = table_for_path(&root_table, &plan.joins, &order.path)?; + if secret.contains(&table, &order.column)? { + crate::sql_log::literal_secret_binds(&value.kind, &value.value, out); + } } } + Ok(()) +} + +/// The secret-value set of one query terminal, the same for the call and +/// its `.sql()`: the secret-typed literals Python collected as it compiled +/// (`python_collected`), and every value the plan binds to a secret column. +/// +/// # Errors +/// As [`plan_secret_values`], and the `PyErr` from converting a value Python +/// collected. +fn query_secret_values( + py: Python<'_>, + name: &str, + plan: &QueryPlan, + python_collected: Option<&Bound<'_, PyAny>>, +) -> PyResult { + let mut out = SecretValues::default(); + secret_binds_from_py(python_collected, &mut out)?; + plan_secret_values(py, &model_class_for(py, name)?, plan, &mut out)?; Ok(out) } -/// The values save payloads bind to the secret columns of `identity`'s -/// model. +/// The secret-value set of a write of `rows` to `identity`'s model: the +/// secret values Python collected from the instances (`python_collected`), +/// and every value a row binds to a secret column. Both name the same +/// values for a declared secret field; the set holds each once. +/// +/// # Errors +/// The `PyErr` from resolving the model class, reading its converter +/// registry, or converting a value. fn payload_secret_values( py: Python<'_>, identity: &str, rows: &[Bound<'_, pyo3::types::PyDict>], -) -> PyResult> { + python_collected: Option<&Bound<'_, PyAny>>, +) -> PyResult { + let mut out = SecretValues::default(); + secret_binds_from_py(python_collected, &mut out)?; let cls = model_class_for(py, identity)?; let columns = crate::sql_log::secret_columns_for(py, &cls)?; - let mut out = Vec::new(); for row in rows { for column in &columns { if let Some(value) = row.get_item(column)? && !value.is_none() { - out.push(python_to_engine_bind_value(&value)?); + out.insert(python_to_engine_bind_value(&value)?); } } } Ok(out) } -/// The secret-value set of an operation: what Python collected, plus what -/// the entry found bound to secret columns. -fn operation_secret_values( - python_collected: &[Bound<'_, PyAny>], - found: Vec, -) -> PyResult> { - let mut values = secret_binds_from_py(python_collected)?; - values.extend(found); - Ok(values) -} - /// One execution route for an operation: a transaction's dedicated /// connection, or the routed engine's pool (FF-G G2). /// @@ -2897,21 +2940,23 @@ fn build_update_by_pk_sql( /// Returns a `PyErr` if the engine is not initialized, the model is not /// registered, the mode is unknown, or a column value cannot be bound. #[pyfunction] -#[pyo3(signature = (name, data, route, mode="insert", *, secret_values=Vec::new()))] +#[pyo3(signature = (name, data, route, mode="insert", *, secret_values=None))] pub fn save_record<'py>( py: Python<'py>, name: String, data: Bound<'py, pyo3::types::PyDict>, route: Py, mode: &str, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let bind_inputs = bind_inputs_from_py(&data)?; // GIL held here, before the async move let mode = parse_save_mode(mode)?; let log = operation_log(py, "save", &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - payload_secret_values(py, &name, std::slice::from_ref(&data))?, + payload_secret_values( + py, + &name, + std::slice::from_ref(&data), + secret_values.as_ref(), ) })?; let operation = async move { @@ -3001,19 +3046,21 @@ pub fn save_record<'py>( /// is missing/null; `PyRuntimeError` on registry failures; typed /// `ferro.exceptions` subclasses on database errors. #[pyfunction] -#[pyo3(signature = (name, data, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, data, route, *, secret_values=None))] pub fn update_record<'py>( py: Python<'py>, name: String, data: Bound<'py, pyo3::types::PyDict>, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let bind_inputs = bind_inputs_from_py(&data)?; // GIL held here, before the async move let log = operation_log(py, "save", &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - payload_secret_values(py, &name, std::slice::from_ref(&data))?, + payload_secret_values( + py, + &name, + std::slice::from_ref(&data), + secret_values.as_ref(), ) })?; let operation = async move { @@ -3109,20 +3156,20 @@ pub fn update_record<'py>( /// # Errors /// `PyRuntimeError` on registry/execute failures; `PyTypeError` for unbindable values. #[pyfunction] -#[pyo3(signature = (name, rows, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, rows, route, *, secret_values=None))] pub fn save_bulk_records<'py>( py: Python<'py>, name: String, rows: Vec>, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let record_inputs: Vec> = rows .iter() .map(bind_inputs_from_py) .collect::>()?; let log = operation_log(py, "bulk_create", &route.get().connection_name, |py| { - operation_secret_values(&secret_values, payload_secret_values(py, &name, &rows)?) + payload_secret_values(py, &name, &rows, secret_values.as_ref()) })?; let operation = async move { let r = route.get(); @@ -3560,7 +3607,7 @@ async fn build_fetch( /// projected records. #[pyfunction] #[pyo3(signature = ( - cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() + cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=None ))] pub fn fetch_filtered<'py>( py: Python<'py>, @@ -3569,7 +3616,7 @@ pub fn fetch_filtered<'py>( route: Py, record_cls: Option>, hop_classes: Option>, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let name = crate::state::model_identity(&cls)?; let (mut plan, request) = fetch_request(&query_ir_json, record_cls, hop_classes)?; @@ -3581,10 +3628,7 @@ pub fn fetch_filtered<'py>( } = request; let cls_py = cls.unbind(); let log = operation_log(py, "fetch", &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - plan_secret_values(py, cls_py.bind(py), &plan)?, - ) + query_secret_values(py, &name, &plan, secret_values.as_ref()) })?; let operation = async move { @@ -3979,7 +4023,7 @@ async fn build_count( /// tx_id (str | None): Optional active transaction. /// using (str | None): Connection override. /// session_id (str | None): Session-scoped routing when set. -/// secret_values (list[object]): The secret-typed literals the query +/// secret_values (Iterable[object]): The secret-typed literals the query /// compiled with, masked in the statement log. /// operation (str): `"count"`, or `"exists"` when the count answers /// `exists()`; names the statement-log records. @@ -3991,21 +4035,18 @@ async fn build_count( /// `PyRuntimeError` on registry, planning, or SQL failures; `PyValueError` /// for an unknown `operation`. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new(), operation="count"))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None, operation="count"))] pub fn count_filtered<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, operation: &str, ) -> PyResult> { let (mut plan, operation) = count_plan(&query_ir_json, operation)?; let log = operation_log(py, operation, &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - ) + query_secret_values(py, &name, &plan, secret_values.as_ref()) })?; let operation = async move { @@ -4236,20 +4277,17 @@ async fn build_delete( /// # Errors /// `PyRuntimeError` on planning or execute failure. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None))] pub fn delete_filtered<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let mut plan = delete_plan(&query_ir_json)?; let log = operation_log(py, "delete", &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - ) + query_secret_values(py, &name, &plan, secret_values.as_ref()) })?; let operation = async move { @@ -4385,20 +4423,17 @@ async fn build_update( /// # Errors /// `PyTypeError` for unbindable column values; `PyRuntimeError` on execute failure. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None))] pub fn update_filtered<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let mut plan = update_plan(&name, &query_ir_json)?; let log = operation_log(py, "update", &route.get().connection_name, |py| { - operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - ) + query_secret_values(py, &name, &plan, secret_values.as_ref()) })?; let operation = async move { let r = route.get(); @@ -4447,12 +4482,13 @@ pub fn update_filtered<'py>( /// The `PyErr` from converting a bind to Python. fn rendered_parts( statement: &BuiltStatement, - secrets: &[EngineBindValue], + secrets: &SecretValues, backend: Dialect, ) -> PyResult> { use pyo3::IntoPyObjectExt; + let mask = secrets.mask(&statement.binds); Python::attach(|py| { - let (params, mask) = crate::sql_log::shown_params(py, &statement.binds, secrets)?; + let (params, mask) = crate::sql_log::shown_params(py, &statement.binds, &mask)?; Ok(pyo3::types::PyTuple::new( py, [ @@ -4496,7 +4532,7 @@ macro_rules! render_on_route { /// route (RouteHandle): The resolved route. /// record_cls (PyAny | None): As for `fetch_filtered`. /// hop_classes (dict[str, type] | None): As for `fetch_filtered`. -/// secret_values (list[object]): The secret-typed literals the query +/// secret_values (Iterable[object]): The secret-typed literals the query /// compiled with, masked in the answer. /// /// Returns: @@ -4507,7 +4543,7 @@ macro_rules! render_on_route { /// The errors `fetch_filtered` raises before it sends. #[pyfunction] #[pyo3(signature = ( - cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=Vec::new() + cls, query_ir_json, route, record_cls=None, hop_classes=None, *, secret_values=None ))] pub fn render_fetch<'py>( py: Python<'py>, @@ -4516,11 +4552,11 @@ pub fn render_fetch<'py>( route: Py, record_cls: Option>, hop_classes: Option>, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let name = crate::state::model_identity(&cls)?; let (mut plan, request) = fetch_request(&query_ir_json, record_cls, hop_classes)?; - let secrets = operation_secret_values(&secret_values, plan_secret_values(py, &cls, &plan)?)?; + let secrets = query_secret_values(py, &name, &plan, secret_values.as_ref())?; let log = operation_log(py, "fetch", &route.get().connection_name, no_secrets)?; let rendering = async move { render_on_route!(route, secrets, |engine, exec, backend| async { @@ -4547,7 +4583,7 @@ pub fn render_fetch<'py>( /// name (str): Model class name. /// query_ir_json (str): Serialized Query IR envelope JSON. /// route (RouteHandle): The resolved route. -/// secret_values (list[object]): The secret-typed literals the query +/// secret_values (Iterable[object]): The secret-typed literals the query /// compiled with, masked in the answer. /// operation (str): `"count"` or `"exists"`, as for `count_filtered`. /// @@ -4558,20 +4594,17 @@ pub fn render_fetch<'py>( /// # Errors /// The errors `count_filtered` raises before it sends. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new(), operation="count"))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None, operation="count"))] pub fn render_count<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, operation: &str, ) -> PyResult> { let (mut plan, operation) = count_plan(&query_ir_json, operation)?; - let secrets = operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - )?; + let secrets = query_secret_values(py, &name, &plan, secret_values.as_ref())?; let log = operation_log(py, operation, &route.get().connection_name, no_secrets)?; let rendering = async move { render_on_route!(route, secrets, |engine, exec, backend| build_count( @@ -4588,7 +4621,7 @@ pub fn render_count<'py>( /// name (str): Model class name. /// query_ir_json (str): Serialized Query IR envelope JSON. /// route (RouteHandle): The resolved route. -/// secret_values (list[object]): The secret-typed literals the query +/// secret_values (Iterable[object]): The secret-typed literals the query /// compiled with, masked in the answer. /// /// Returns: @@ -4598,19 +4631,16 @@ pub fn render_count<'py>( /// # Errors /// The errors `update_filtered` raises before it sends. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None))] pub fn render_update<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let mut plan = update_plan(&name, &query_ir_json)?; - let secrets = operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - )?; + let secrets = query_secret_values(py, &name, &plan, secret_values.as_ref())?; let log = operation_log(py, "update", &route.get().connection_name, no_secrets)?; let rendering = async move { render_on_route!(route, secrets, |engine, exec, backend| build_update( @@ -4627,7 +4657,7 @@ pub fn render_update<'py>( /// name (str): Model class name. /// query_ir_json (str): Serialized Query IR envelope JSON. /// route (RouteHandle): The resolved route. -/// secret_values (list[object]): The secret-typed literals the query +/// secret_values (Iterable[object]): The secret-typed literals the query /// compiled with, masked in the answer. /// /// Returns: @@ -4637,19 +4667,16 @@ pub fn render_update<'py>( /// # Errors /// The errors `delete_filtered` raises before it sends. #[pyfunction] -#[pyo3(signature = (name, query_ir_json, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (name, query_ir_json, route, *, secret_values=None))] pub fn render_delete<'py>( py: Python<'py>, name: String, query_ir_json: String, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let mut plan = delete_plan(&query_ir_json)?; - let secrets = operation_secret_values( - &secret_values, - plan_secret_values(py, &model_class_for(py, &name)?, &plan)?, - )?; + let secrets = query_secret_values(py, &name, &plan, secret_values.as_ref())?; let log = operation_log(py, "delete", &route.get().connection_name, no_secrets)?; let rendering = async move { render_on_route!(route, secrets, |engine, exec, backend| build_delete( @@ -5357,14 +5384,14 @@ fn get_raw_tx_conn( /// not a supported primitive (the Python `_marshal` wrapper guarantees this /// never trips in normal use). #[pyfunction] -#[pyo3(signature = (sql, args, route, autocommit=false, *, secret_values=Vec::new()))] +#[pyo3(signature = (sql, args, route, autocommit=false, *, secret_values=None))] pub fn raw_execute<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, autocommit: bool, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -5384,7 +5411,7 @@ pub fn raw_execute<'py>( }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; let log = operation_log(py, "raw", &route_connection_name, |_| { - secret_binds_from_py(&secret_values) + python_secret_values(secret_values.as_ref()) })?; let operation = async move { @@ -5428,13 +5455,13 @@ pub fn raw_execute<'py>( /// UUID/datetime/JSON columns come back as strings — Ferro does not decode them /// for raw SQL. If you want typed rows, use the ORM. #[pyfunction] -#[pyo3(signature = (sql, args, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (sql, args, route, *, secret_values=None))] pub fn raw_fetch_all<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -5450,7 +5477,7 @@ pub fn raw_fetch_all<'py>( }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; let log = operation_log(py, "raw", &route_connection_name, |_| { - secret_binds_from_py(&secret_values) + python_secret_values(secret_values.as_ref()) })?; let operation = async move { @@ -5501,13 +5528,13 @@ pub fn raw_fetch_all<'py>( /// Values are wire-close primitives (`str | int | float | bool | bytes | None`). /// UUID/datetime/JSON columns come back as strings — use the ORM for typed hydration. #[pyfunction] -#[pyo3(signature = (sql, args, route, *, secret_values=Vec::new()))] +#[pyo3(signature = (sql, args, route, *, secret_values=None))] pub fn raw_fetch_one<'py>( py: Python<'py>, sql: String, args: Vec>, route: Py, - secret_values: Vec>, + secret_values: Option>, ) -> PyResult> { let bind_values: Vec = args .iter() @@ -5523,7 +5550,7 @@ pub fn raw_fetch_one<'py>( }; let tx_conn = get_raw_tx_conn(route_tx_id, route_session_id.as_deref())?; let log = operation_log(py, "raw", &route_connection_name, |_| { - secret_binds_from_py(&secret_values) + python_secret_values(secret_values.as_ref()) })?; let operation = async move { diff --git a/src/sql_log.rs b/src/sql_log.rs index 3c8cde6d..51976aa1 100644 --- a/src/sql_log.rs +++ b/src/sql_log.rs @@ -83,8 +83,8 @@ pub struct StatementContext { /// The table, enum type or step file the statement belongs to, when /// there is one (see [`with_subject`]). pub subject: Option, - /// Bound values a record shows as `***`. - pub secret_values: Vec, + /// Bound values a record shows as `***`, shared by every nested scope. + pub secret_values: Arc, } impl StatementContext { @@ -95,7 +95,7 @@ impl StatementContext { operation, connection: connection.into(), subject: None, - secret_values: Vec::new(), + secret_values: Arc::new(SecretValues::default()), } } } @@ -205,6 +205,98 @@ pub async fn with_operation(operation: &'static str, fut: F) -> F::Ou } } +/// An operation's secret-value set: every value a record shows as `***`. +/// +/// A bind is masked when it equals a member, so redaction costs one hash +/// lookup per bind however many secrets the operation carries (a +/// `bulk_create` of 100k rows carries 100k), and a value collected twice (by +/// Python from a `SecretStr`, and by the engine from the secret column it is +/// bound to) is held once. Text and bytes, the shapes a secret takes, are +/// looked up without copying the bind. Any other value is held by its +/// equality class (a float by its bits, `-0.0` as `0.0`), so membership +/// agrees with `EngineBindValue`'s own equality except that a `NaN` matches +/// a `NaN`, which over-masks. `NULL` is never a secret. +#[derive(Clone, Debug, Default, PartialEq)] +pub struct SecretValues { + text: HashSet, + bytes: HashSet>, + scalars: HashSet, +} + +/// A secret that is neither text nor bytes, in a hashable form. +#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)] +enum SecretScalar { + Bool(bool), + I64(i64), + F64(u64), + Uuid(sqlx::types::Uuid), +} + +impl SecretScalar { + fn of(value: &EngineBindValue) -> Option { + match value { + EngineBindValue::Bool(value) => Some(Self::Bool(*value)), + EngineBindValue::I64(value) => Some(Self::I64(*value)), + EngineBindValue::F64(value) => Some(Self::F64(if *value == 0.0 { + 0.0_f64.to_bits() + } else { + value.to_bits() + })), + EngineBindValue::Uuid(value) => Some(Self::Uuid(*value)), + EngineBindValue::String(_) | EngineBindValue::Bytes(_) | EngineBindValue::Null(_) => { + None + } + } + } +} + +impl SecretValues { + /// Add `value` to the set; a `NULL` is ignored. + pub fn insert(&mut self, value: EngineBindValue) { + match value { + EngineBindValue::String(text) => { + self.text.insert(text); + } + EngineBindValue::Bytes(bytes) => { + self.bytes.insert(bytes); + } + other => { + if let Some(scalar) = SecretScalar::of(&other) { + self.scalars.insert(scalar); + } + } + } + } + + /// Whether `bind` equals a member: one lookup. + pub fn contains(&self, bind: &EngineBindValue) -> bool { + match bind { + EngineBindValue::String(text) => self.text.contains(text.as_str()), + EngineBindValue::Bytes(bytes) => self.bytes.contains(bytes.as_slice()), + other => SecretScalar::of(other).is_some_and(|scalar| self.scalars.contains(&scalar)), + } + } + + /// The number of distinct secret values. + #[cfg(test)] + fn len(&self) -> usize { + self.text.len() + self.bytes.len() + self.scalars.len() + } + + /// Which of `binds` are secret, position by position. + pub fn mask(&self, binds: &[EngineBindValue]) -> Vec { + binds.iter().map(|bind| self.contains(bind)).collect() + } +} + +impl Extend for SecretValues { + fn extend>(&mut self, values: I) { + for value in values { + self.insert(value); + } + } +} + /// The columns of `cls` whose field is a `SecretStr` / `SecretBytes`: the /// fields its hydration-converter registry records with kind `"secret"`. /// @@ -222,16 +314,16 @@ pub fn secret_columns_for(py: Python<'_>, cls: &Bound<'_, PyAny>) -> PyResult) { +pub fn literal_secret_binds(kind: &str, value: &serde_json::Value, out: &mut SecretValues) { match value { - serde_json::Value::String(text) => out.push(EngineBindValue::String(text.clone())), + serde_json::Value::String(text) => out.insert(EngineBindValue::String(text.clone())), serde_json::Value::Array(items) if kind == "bytes" => { let bytes: Option> = items .iter() .map(|item| item.as_u64().and_then(|byte| u8::try_from(byte).ok())) .collect(); if let Some(bytes) = bytes { - out.push(EngineBindValue::Bytes(bytes)); + out.insert(EngineBindValue::Bytes(bytes)); } } serde_json::Value::Array(items) => { @@ -257,12 +349,16 @@ pub fn observe( return; }; let duration_ms = started.elapsed().as_secs_f64() * 1000.0; + // Decided before the GIL is taken, which is held only to hand the + // record over. + let mask = active.context.secret_values.mask(binds); let written = Python::attach(|py| { emit( py, &active.context, sql, binds, + &mask, dialect, duration_ms, outcome, @@ -273,27 +369,22 @@ pub fn observe( } } -/// Which of `binds` are secret: equal to one of `secrets`. -fn mask_of(binds: &[EngineBindValue], secrets: &[EngineBindValue]) -> Vec { - binds.iter().map(|bind| secrets.contains(bind)).collect() -} - /// A statement's parameters as a record shows them: each bind as its -/// Python value, `None` where it equals one of `secrets`, beside the mask -/// that marks those positions. The statement log and a rendered statement -/// (`.sql()`) both show parameters through this one function. +/// Python value, `None` where `mask` marks it secret, beside the mask +/// itself. The statement log and a rendered statement (`.sql()`) both show +/// parameters through this one function, with the mask +/// [`SecretValues::mask`] decides. /// /// # Errors /// The `PyErr` from converting a bind to Python. pub fn shown_params<'py>( py: Python<'py>, binds: &[EngineBindValue], - secrets: &[EngineBindValue], + mask: &[bool], ) -> PyResult<(Bound<'py, PyTuple>, Bound<'py, PyTuple>)> { - let mask = mask_of(binds, secrets); let params = binds .iter() - .zip(&mask) + .zip(mask) .map(|(bind, &masked)| { if masked { Ok(py.None().into_bound(py)) @@ -333,16 +424,18 @@ fn bind_to_py<'py>(py: Python<'py>, bind: &EngineBindValue) -> PyResult, context: &StatementContext, sql: &str, binds: &[EngineBindValue], + mask: &[bool], dialect: Dialect, duration_ms: f64, outcome: Result, &sqlx::Error>, ) -> PyResult<()> { - let (params, mask) = shown_params(py, binds, &context.secret_values)?; + let (params, mask) = shown_params(py, binds, mask)?; let (rows, error) = match outcome { Ok(rows) => (rows, None), Err(err) => (None, Some(err.to_string())), @@ -373,6 +466,12 @@ mod tests { use super::*; use crate::backend::NullKind; + fn secrets(values: impl IntoIterator) -> SecretValues { + let mut set = SecretValues::default(); + set.extend(values); + set + } + #[test] fn a_bind_is_masked_when_it_equals_a_secret_value() { let secret = EngineBindValue::String("hunter2".into()); @@ -381,16 +480,64 @@ mod tests { secret.clone(), EngineBindValue::Null(NullKind::String), ]; - assert_eq!(mask_of(&binds, &[secret]), vec![false, true, false]); - assert_eq!(mask_of(&binds, &[]), vec![false, false, false]); + assert_eq!(secrets([secret]).mask(&binds), vec![false, true, false]); + assert_eq!( + SecretValues::default().mask(&binds), + vec![false, false, false] + ); + } + + #[test] + fn a_value_collected_twice_is_held_once() { + // Python's `SecretStr` and the engine's secret column name the same + // value for every row of a bulk_create; the set holds each once. + let rows = (0..1000).map(|i| EngineBindValue::String(format!("sk_{i}"))); + let set = secrets(rows.clone().chain(rows)); + assert_eq!(set.len(), 1000); + } + + #[test] + fn membership_is_by_value_for_every_kind_of_bind() { + let uuid = sqlx::types::Uuid::nil(); + let set = secrets([ + EngineBindValue::String("s".into()), + EngineBindValue::Bytes(vec![0, 255]), + EngineBindValue::I64(7), + EngineBindValue::F64(-0.0), + EngineBindValue::Bool(true), + EngineBindValue::Uuid(uuid), + EngineBindValue::Null(NullKind::String), + ]); + assert_eq!(set.len(), 6, "NULL is never a secret"); + for bind in [ + EngineBindValue::String("s".into()), + EngineBindValue::Bytes(vec![0, 255]), + EngineBindValue::I64(7), + EngineBindValue::F64(0.0), + EngineBindValue::Bool(true), + EngineBindValue::Uuid(uuid), + ] { + assert!(set.contains(&bind), "{bind:?} is a member"); + } + for bind in [ + EngineBindValue::String("t".into()), + EngineBindValue::Bytes(b"s".to_vec()), + EngineBindValue::I64(8), + EngineBindValue::F64(7.0), + EngineBindValue::Bool(false), + EngineBindValue::Null(NullKind::String), + EngineBindValue::Null(NullKind::Untyped), + ] { + assert!(!set.contains(&bind), "{bind:?} is not a member"); + } } #[test] fn shown_params_puts_none_where_a_bind_is_secret() { let secret = EngineBindValue::String("hunter2".into()); let shown = Python::attach(|py| -> PyResult<(String, String)> { - let (params, mask) = - shown_params(py, &[EngineBindValue::I64(7), secret.clone()], &[secret])?; + let binds = [EngineBindValue::I64(7), secret.clone()]; + let (params, mask) = shown_params(py, &binds, &secrets([secret]).mask(&binds))?; Ok((params.repr()?.to_string(), mask.repr()?.to_string())) }); match shown { @@ -458,19 +605,19 @@ mod tests { #[test] fn literal_secret_binds_reads_strings_bytes_and_lists() { - let mut out = Vec::new(); + let mut out = SecretValues::default(); literal_secret_binds("string", &serde_json::json!("hunter2"), &mut out); literal_secret_binds("bytes", &serde_json::json!([0, 255]), &mut out); literal_secret_binds("list", &serde_json::json!(["a", "b"]), &mut out); literal_secret_binds("int", &serde_json::json!(7), &mut out); assert_eq!( out, - vec![ + secrets([ EngineBindValue::String("hunter2".into()), EngineBindValue::Bytes(vec![0, 255]), EngineBindValue::String("a".into()), EngineBindValue::String("b".into()), - ] + ]) ); } diff --git a/tests/test_rendered_statement.py b/tests/test_rendered_statement.py index 58c25d26..181b628b 100644 --- a/tests/test_rendered_statement.py +++ b/tests/test_rendered_statement.py @@ -170,6 +170,45 @@ def _sentinel_positions(params: tuple[object, ...]) -> list[int]: {}, True, ), + ( + "all-after-plain-position-on-a-secret-key", + lambda ada: ( + RsAccount.select() + .order_by(lambda account: account.token) + .order_by(lambda account: account.id) + .after(("sk_live_CURSOR", 0)) + .all + ), + (), + {}, + True, + ), + ( + "all-before-plain-position-on-a-secret-key", + lambda ada: ( + RsAccount.select() + .order_by(lambda account: account.token) + .order_by(lambda account: account.id) + .before(("sk_live_CURSOR", 0)) + .all + ), + (), + {}, + True, + ), + ( + "first-after-plain-position-on-a-traversed-secret-key", + lambda ada: ( + RsNote.select() + .order_by(lambda note: note.account.token) + .order_by(lambda note: note.id) + .after(("sk_live_CURSOR", 0)) + .first + ), + (), + {}, + True, + ), ("relation-all", lambda ada: ada.notes.all, (), {}, False), ("relation-first", lambda ada: ada.notes.first, (), {}, False), ] diff --git a/tests/test_statement_log.py b/tests/test_statement_log.py index b07e414a..d6327eb7 100644 --- a/tests/test_statement_log.py +++ b/tests/test_statement_log.py @@ -16,6 +16,7 @@ """ import logging +import time from typing import Annotated import pytest @@ -821,6 +822,43 @@ async def test_a_secret_literal_against_a_plain_column_is_redacted( _assert_hidden(statement_records, "ada@example.com") +@pytest.mark.asyncio +async def test_a_plain_position_on_a_secret_order_key_is_redacted( + db_url, statement_records +): + """A page token decodes to a plain `str`, and a keyset position binds it + against its order key: on a secret key it is masked like any value bound + to a secret column, forward, backward and through a traversed key.""" + await _connect(db_url) + async with engines.session(): + ada = _ada() + await ada.save() + await SlogNote(id=1, label="hello", account=ada).save() + statement_records.clear() + + by_token = ( + SlogAccount.select() + .order_by(lambda account: account.token) + .order_by(lambda account: account.id) + ) + await by_token.after(("sk_live_CURSOR", 0)).all() + await by_token.before(("sk_live_CURSOR", 0)).all() + await ( + SlogNote.select() + .order_by(lambda note: note.account.token) + .order_by(lambda note: note.id) + .after(("sk_live_CURSOR", 0)) + .all() + ) + + records = _sent(statement_records) + assert len(records) == 3 + for record in records: + assert REDACTED in record.params + assert 0 in record.params + _assert_hidden(statement_records, "sk_live_CURSOR") + + @pytest.mark.asyncio async def test_a_secret_raw_argument_is_redacted(db_url, db_backend, statement_records): await _connect(db_url) @@ -846,32 +884,36 @@ async def test_a_secret_raw_argument_is_redacted(db_url, db_backend, statement_r @pytest.mark.asyncio -async def test_with_the_log_off_no_operation_emits_or_collects_secrets( - db_url, db_backend, monkeypatch +@pytest.mark.parametrize("logged", [True, False], ids=["log-on", "log-off"]) +async def test_secret_values_are_collected_once_and_only_when_needed( + db_url, db_backend, monkeypatch, logged ): - import ferro.models - import ferro.raw - - calls: list[dict] = [] - collected: list[str] = [] - monkeypatch.setattr(ferro._sql_log, "emit", calls.append) - for module, name in ( - (ferro.models, "secret_values"), - (ferro.raw, "secret_values_of"), - ): - original = getattr(module, name) - - def counting(*args, _original=original, _name=name, **kwargs): - collected.append(_name) - return _original(*args, **kwargs) - - monkeypatch.setattr(module, name, counting) + """Every operation collects its secret values through one function, + `ferro._bind_payload.secret_values_in`. A query collects them once, as it + compiles, because its `.sql()` masks with the same values; every other + operation collects them only when the engine, reading the log's one + switch, asks for them. With the log off nothing is emitted.""" + import ferro._bind_payload + + emitted: list[dict] = [] + collected: list[object] = [] + collect = ferro._bind_payload.secret_values_in + + def counting(values): + found = collect(values) + collected.append(found) + return found + + monkeypatch.setattr(ferro._sql_log, "emit", emitted.append) + monkeypatch.setattr(ferro._bind_payload, "secret_values_in", counting) logger = logging.getLogger("ferro.sql") level = logger.level - logger.setLevel(logging.WARNING) + logger.setLevel(logging.DEBUG if logged else logging.WARNING) + ph = _ph(db_backend) try: await _connect(db_url) async with engines.session(): + collected.clear() account = _ada() await account.save() account.token = SecretStr("sk_live_2") @@ -879,18 +921,80 @@ def counting(*args, _original=original, _name=name, **kwargs): await SlogAccount.bulk_create( [SlogAccount(id=2, email="b@example.com", token=SecretStr("sk_b"))] ) - await SlogAccount.where(lambda account: account.token == "sk_b").count() - await raw.execute( - f"UPDATE slogaccount SET token = {_ph(db_backend)}", - SecretStr("sk_live_3"), - ) + await raw.execute(f"UPDATE slogaccount SET token = {ph}", SecretStr("sk_3")) + await raw.fetch_one(f"SELECT id FROM slogaccount WHERE token = {ph}", "x") + await raw.fetch_all(f"SELECT id FROM slogaccount WHERE id = {ph}", 1) async with transaction(): await SlogTag(id=1, name="a").save() + writes = list(collected) + + collected.clear() + by_token = SlogAccount.where(lambda account: account.token == "sk_b") + await by_token.first() + await by_token.count() + await by_token.exists() + await by_token.update(token=SecretStr("sk_c")) + await SlogAccount.where(lambda account: account.token == "sk_c").delete() + await account.delete() + queries = list(collected) finally: logger.setLevel(level) - assert calls == [] - assert collected == [] + assert len(queries) == 6 + if logged: + assert len(writes) == 7 + assert ("sk_live_1", b"k\x00\xff") in writes + assert emitted + else: + assert writes == [] + assert emitted == [] + + +class _Discard(logging.Handler): + """Handles every record and keeps none.""" + + def emit(self, record: logging.LogRecord) -> None: + pass + + +async def _timed_bulk_create(first_id: int, rows: int) -> float: + started = time.perf_counter() + async with engines.session(): + await SlogAccount.bulk_create( + [ + SlogAccount( + id=first_id + i, + email=f"{first_id + i}@example.com", + token=SecretStr(f"sk_{first_id + i}"), + ) + for i in range(rows) + ] + ) + return time.perf_counter() - started + + +@pytest.mark.asyncio +async def test_redacting_a_bulk_create_costs_one_lookup_per_bind(db_url): + """Each bind is one lookup in the operation's secret-value set, so the log + adds cost in proportion to the rows. Matched against a list of every + row's secret, every chunk scanned all of them: 20k rows took seconds + with the log on against a tenth of a second off.""" + rows = 20_000 + await _connect(db_url) + logger = logging.getLogger("ferro.sql") + level = logger.level + handler = _Discard(level=logging.DEBUG) + logger.addHandler(handler) + try: + logger.setLevel(logging.WARNING) + off = await _timed_bulk_create(0, rows) + logger.setLevel(logging.DEBUG) + on = await _timed_bulk_create(rows, rows) + finally: + logger.removeHandler(handler) + logger.setLevel(level) + + assert on < 4 * off + 1.0, f"log on {on:.2f}s against log off {off:.2f}s" @pytest.mark.asyncio From 2b9607284fc91b02d8ba32240de85d7d5c5d5811 Mon Sep 17 00:00:00 2001 From: 0x54 Date: Wed, 21 Oct 2026 08:32:12 -0400 Subject: [PATCH 5/5] =?UTF-8?q?fix(log):=20panel=20round=201=20for=20#764?= =?UTF-8?q?=20=E2=80=94=20run-lock=20statements=20in=20the=20log,=20pool?= =?UTF-8?q?=20hooks=20excluded,=20operation=20values=20documented=20(#773)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Panel findings F3, F9 and F8 on PR #771: the run lock's pg_try_advisory_lock, held-by-session probe and pg_advisory_unlock go through a logged detached fetch in the engine layer and are migrate records; pool hooks (after_connect search_path, the after_release guard) are stated as excluded from the statement log in the Connections guide and a dated ADR-0057 paragraph, since logging them would take the GIL per connection open/release and sqlx runs the release hook on a spawned task; the Connections guide lists every operation value and subject. Interfaces changed: none Part of #700 (panel round 1 on PR #771) Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP --- ...h-the-statement-log-and-a-terminals-sql.md | 4 + docs/pages/guide/connections.md | 18 ++- src/backend.rs | 47 +++++-- src/run.rs | 62 ++++++--- tests/test_statement_log_run.py | 120 ++++++++++++++++++ 5 files changed, 220 insertions(+), 31 deletions(-) create mode 100644 tests/test_statement_log_run.py diff --git a/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md b/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md index 67a7f2e3..18589fe0 100644 --- a/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md +++ b/docs/adr/0057-sql-is-seen-through-the-statement-log-and-a-terminals-sql.md @@ -38,3 +38,7 @@ A bound value shows as `***`, a sentinel whose `repr` is `***` so a test can tel Amended 2026-10-21 (panel F11 on #771): the mask is a set of values, not a positional flag. The binds are made by the query builder in Rust and never pass through Python one by one, so Python cannot mark positions. Instead each operation has one *secret-value set*, built from two facts. Python collects what every `SecretStr` / `SecretBytes` it unwraps hides (a query's literals as it compiles, a write's field values, a raw statement's arguments) through one collector. Rust adds every value the operation binds to a column whose field is declared secret: predicate literals, literal `SET`s, keyset positions (`after` / `before`) on a secret order key, root or traversed, and a write's secret-column values. A bind is masked when it equals a member of the set, one hash lookup per bind, decided before the GIL is taken to write the record. So `Account.where(lambda account: account.token == "sk_live_1")` logs `params=(***,)` though `"sk_live_1"` is a plain `str`. A plain parameter that happens to equal a secret of the same operation is masked too (`bulk_create` of one row whose email equals another row's token shows both as `***`): over-redaction, in the safe direction, never a leak. The switch is still read once per operation, by the engine at the operation's entry. A write's or raw statement's Python-collected values reach the engine as a lazy iterable it reads only when the log is on; a query's are collected as it compiles, because its `.sql()` masks with the same values. A pin holds the two doors together: for every terminal on both dialects, `.sql()` equals the record the executed call wrote. + +## Amendment (2026-10-21): pool hooks are not in the statement log + +A Postgres pool sends two statements of its own, outside any operation: the `after_connect` hook's `SET search_path TO …` on each new connection, and, with `settings_delivery="connection"`, the `after_release` guard's `SELECT coalesce(current_setting($1, true), '')` on each returned connection while a session holds a pinned one. They are not in the statement log. A record needs an operation's scope, and these belong to no operation: sqlx runs the release hook on a task it spawns, and opens connections for `min_connections` in its background maintenance, so a scope could reach at most the connects an operation happens to wait on. Logging them would mean asking the logger once per connection opened and once per connection returned, a GIL take on each, which is the per-pool-event cost the one switch exists to avoid. The run lock's statements are not pool hooks: the run sends them on its own session inside its `migrate` scope, so they are records like the DDL around them. diff --git a/docs/pages/guide/connections.md b/docs/pages/guide/connections.md index 0f3fcf2d..8ae2bebe 100644 --- a/docs/pages/guide/connections.md +++ b/docs/pages/guide/connections.md @@ -242,12 +242,28 @@ A statement the database rejects ends its line with `failed: `, and the e | `params` | The bound parameters, as a tuple | | `dialect` | `"sqlite"` or `"postgres"` | | `duration_ms` | Time the database took, in milliseconds | -| `operation` | What sent it: `"migrate"` for the reconciliation pass and `ferro migrate` | +| `operation` | What sent it: one of the values below | | `subject` | The table or enum type a pass statement changes, or the step file (`0003_add_slug/01_add_slug.up.sql`) a migration statement comes from; `None` otherwise | | `connection` | The connection's name | | `rows` | Rows affected, or `None` for a read | | `error` | The database's error text, or `None` | +| `operation` | Sent by | +| --- | --- | +| `"fetch"` | `all()`, `first()`, `get()` and relation loads | +| `"count"` / `"exists"` | `count()` / `exists()` | +| `"save"` | `save()`, insert or update | +| `"bulk_create"` | `bulk_create()`, one record per chunk | +| `"update"` / `"delete"` | A query's `update()` / `delete()`; `delete()` on an instance | +| `"m2m_add"` / `"m2m_remove"` / `"m2m_clear"` | A many-to-many relation's `add()` / `remove()` / `clear()` | +| `"raw"` | `ferro.raw.execute()`, `fetch_all()` and `fetch_one()` | +| `"transaction"` | A `transaction()` block's `BEGIN`, `SAVEPOINT`, `RELEASE`, `ROLLBACK TO`, `COMMIT` and `ROLLBACK` | +| `"settings"` | A session's settings batch (`SET LOCAL`, `set_config`) and its reset | +| `"catalog"` | The Postgres catalog read the first time an operation touches a table | +| `"migrate"` | The reconciliation pass and `ferro migrate`, the run lock's statements included | + +Statements a Postgres pool sends on its own, outside any operation, are not in the log: the `SET search_path` it runs on each new connection, and, with `settings_delivery="connection"`, the check it runs on each returned connection while a session has one pinned. + The logger is the only switch: while `ferro.sql` is not enabled for `DEBUG`, Ferro collects nothing. Ferro installs only a `NullHandler` on its `ferro` logger, which propagates, so your logging configuration (and pytest's `caplog`) decides where the records go. The `ferro` command line installs its own handler, so a data step's `ctx.log.info(...)` lines still print there. ## See Also diff --git a/src/backend.rs b/src/backend.rs index 13cec57c..f70a8092 100644 --- a/src/backend.rs +++ b/src/backend.rs @@ -877,16 +877,7 @@ impl EngineConnection { .await .map(|rows| rows.iter().map(materialize_engine_row).collect()) } - EngineConnection::Postgres(conn) => { - let mut query = sqlx::query(sql).persistent(false); - for value in values { - query = bind_engine_value(query, value); - } - query - .fetch_all(&mut **conn) - .await - .map(|rows| rows.iter().map(materialize_pg_row).collect()) - } + EngineConnection::Postgres(conn) => fetch_all_pg_unprepared(conn, sql, values).await, }; observe_fetch(sql, values, dialect, started, &result); result @@ -1022,6 +1013,42 @@ impl EngineConnection { } } +/// Fetch on a Postgres connection the pool no longer owns, without entering +/// its prepared-statement cache, and write the statement to the statement +/// log: the run lock's own session (`crate::run::RunLock`) sends its +/// `pg_try_advisory_lock`, its held-by-this-session check and its +/// `pg_advisory_unlock` through here, so they are records like any other. +/// +/// # Errors +/// The `sqlx::Error` the database returned; it is in the record too. +pub async fn fetch_all_detached_pg_unprepared( + conn: &mut sqlx::PgConnection, + sql: &str, + values: &[EngineBindValue], +) -> Result, sqlx::Error> { + let started = Instant::now(); + let result = fetch_all_pg_unprepared(conn, sql, values).await; + observe_fetch(sql, values, Dialect::Postgres, started, &result); + result +} + +/// The Postgres fetch both an [`EngineConnection`] and a detached connection +/// send; the caller writes the record. +async fn fetch_all_pg_unprepared( + conn: &mut sqlx::PgConnection, + sql: &str, + values: &[EngineBindValue], +) -> Result, sqlx::Error> { + let mut query = sqlx::query(sql).persistent(false); + for value in values { + query = bind_engine_value(query, value); + } + query + .fetch_all(conn) + .await + .map(|rows| rows.iter().map(materialize_pg_row).collect()) +} + /// The statement log's record of an unbound execute that returned `result`'s /// rows affected. fn observe_rows(sql: &str, dialect: Dialect, started: Instant, result: &Result) { diff --git a/src/run.rs b/src/run.rs index 33435216..7c9b4316 100644 --- a/src/run.rs +++ b/src/run.rs @@ -46,7 +46,7 @@ use ferro_migrate::snapshot::encode_checksum; use ferro_schema_ir::SchemaModel; use once_cell::sync::Lazy; use pyo3::prelude::*; -use sqlx::{Connection, Row}; +use sqlx::Connection; use std::collections::{BTreeMap, HashMap, HashSet}; use std::path::{Path, PathBuf}; use std::sync::Arc; @@ -650,6 +650,28 @@ const HELD_BY_ANY_SESSION: &str = "SELECT EXISTS (SELECT 1 FROM pg_locks \ AND database = (SELECT oid FROM pg_database WHERE datname = current_database()) \ AND classid::bigint = $1 AND objid::bigint = $2)"; +/// Send one of the run lock's statements on its own session and read the +/// boolean it answers. The statement goes through the engine's fetch layer, +/// so it is a record in the statement log under the run's scope. +/// +/// # Errors +/// The database's error; `RowNotFound` or a decode error when the answer is +/// not one boolean. +async fn lock_answer( + conn: &mut sqlx::PgConnection, + sql: &str, + binds: &[EngineBindValue], +) -> Result { + let rows = crate::backend::fetch_all_detached_pg_unprepared(conn, sql, binds).await?; + match rows.first().and_then(|row| column(row, 0)) { + Some(EngineValue::Bool(answer)) => Ok(*answer), + Some(other) => Err(sqlx::Error::Decode( + format!("the run lock's `{sql}` answered {other:?}, not a boolean").into(), + )), + None => Err(sqlx::Error::RowNotFound), + } +} + impl RunLock { /// Take the run lock for the governed `schema` (the connection's current /// schema when `None`), waiting up to `timeout`. `on_wait` is called once, @@ -711,13 +733,13 @@ impl RunLock { .map_err(|e| db_error("opening the run lock's connection", e))? .detach(); loop { - let taken: bool = sqlx::query("SELECT pg_try_advisory_lock($1)") - .bind(key) - .persistent(false) - .fetch_one(&mut conn) - .await - .and_then(|row| row.try_get(0)) - .map_err(|e| db_error("taking the run lock", e))?; + let taken = lock_answer( + &mut conn, + "SELECT pg_try_advisory_lock($1)", + &[EngineBindValue::I64(key)], + ) + .await + .map_err(|e| db_error("taking the run lock", e))?; if taken { break; } @@ -820,13 +842,12 @@ impl RunLock { None => false, Some(conn) => { let (classid, objid) = lock_ids(*key); - let probe = sqlx::query(HELD_BY_THIS_SESSION) - .bind(classid) - .bind(objid) - .persistent(false) - .fetch_one(conn) - .await - .and_then(|row| row.try_get::(0)); + let probe = lock_answer( + conn, + HELD_BY_THIS_SESSION, + &[EngineBindValue::I64(classid), EngineBindValue::I64(objid)], + ) + .await; match probe { Ok(held) => held, Err(err) if !first && probe_lost_the_session(&err) => false, @@ -848,11 +869,12 @@ impl RunLock { match &mut self.state { LockState::Postgres { conn, key, .. } => { if let Some(mut conn) = conn.take() { - let _ = sqlx::query("SELECT pg_advisory_unlock($1)") - .bind(*key) - .persistent(false) - .execute(&mut conn) - .await; + let _ = lock_answer( + &mut conn, + "SELECT pg_advisory_unlock($1)", + &[EngineBindValue::I64(*key)], + ) + .await; let _ = conn.close().await; } } diff --git a/tests/test_statement_log_run.py b/tests/test_statement_log_run.py new file mode 100644 index 00000000..dc77adbe --- /dev/null +++ b/tests/test_statement_log_run.py @@ -0,0 +1,120 @@ +# ruff: noqa: F811 - pytest fixtures imported from a sibling module are redefined as arguments +"""The run lock's statements are in the statement log (#764, ADR-0057). + +On Postgres a run holds its lock as a session advisory lock on a connection +of its own. Taking it, checking it and letting it go are statements like any +other, so a run's log shows them among its DDL: + +```text +ferro.sql DEBUG SELECT pg_try_advisory_lock($1) params=(4242...,) 0.4ms +ferro.sql DEBUG SELECT EXISTS (SELECT 1 FROM pg_locks ...) params=(...) 0.6ms +ferro.sql DEBUG CREATE TABLE "slog_author" (...) params=() 1.2ms +ferro.sql DEBUG SELECT pg_advisory_unlock($1) params=(4242...,) 0.3ms +``` + +SQLite's run lock is a file lock and sends no statement. +""" + +import logging +from typing import Annotated + +import pytest + +import ferro +from ferro import Model +from ferro.base import FerroField +from ferro.migrations.testing import harness +from tests.test_migrate_new import ( # noqa: F401 - fixtures + pkg, + project, + write_models, +) +from tests.test_migrate_up import ( # noqa: F401 - fixtures + configure, + db, + new, +) + +pytestmark = [pytest.mark.postgres_only, pytest.mark.asyncio] + +TRY_LOCK = "SELECT pg_try_advisory_lock($1)" +UNLOCK = "SELECT pg_advisory_unlock($1)" +PROBE_PREFIX = "SELECT EXISTS (SELECT 1 FROM pg_locks" + + +def _is_probe(sql: str) -> bool: + """The check that this run's own session holds the lock (``status``'s + probe of any session's lock reads the same view without the pid).""" + return sql.startswith(PROBE_PREFIX) and "pg_backend_pid()" in sql + + +AUTHOR = """ +class Author(Model): + __ferro_table__ = "slog_author" + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str +""" + + +def _lock_records(records: list[logging.LogRecord]) -> list[logging.LogRecord]: + return [r for r in records if r.sql in (TRY_LOCK, UNLOCK) or _is_probe(r.sql)] + + +def _assert_lock_lifecycle(records: list[logging.LogRecord]) -> None: + """The lock is taken, checked on its own session, then released, each one + record under ``operation="migrate"``, around every other statement of the + run.""" + lock = _lock_records(records) + assert [r.sql for r in lock][:1] == [TRY_LOCK] + assert _is_probe(lock[1].sql) + assert lock[-1].sql == UNLOCK + key = lock[0].params + assert len(key) == 1 and isinstance(key[0], int) + assert lock[-1].params == key + assert len(lock[1].params) == 2 and all(isinstance(p, int) for p in lock[1].params) + for record in lock: + assert record.operation == "migrate" + assert record.subject is None + assert record.connection == "default" + assert record.dialect == "postgres" + assert record.error is None + assert record.duration_ms >= 0 + first, last = records.index(lock[0]), records.index(lock[-1]) + ddl = [r for r in records if r.sql.startswith("CREATE TABLE")] + assert ddl and all(first < records.index(r) < last for r in ddl) + + +@pytest.mark.usefixtures("isolated_imports", "clean_registry") +async def test_a_run_logs_taking_checking_and_releasing_its_lock( + project, pkg, db, statement_records +): + configure(project, pkg, db.backend) + write_models(project, pkg, AUTHOR) + new("create_author") + await ferro.connect(db.url) + try: + await harness().apply("0001") + finally: + ferro.reset_engine() + + _assert_lock_lifecycle(statement_records) + + +@pytest.fixture +def _fresh(clean_registry): + yield + ferro.reset_engine() + + +@pytest.mark.usefixtures("_fresh") +async def test_the_reconciliation_pass_logs_its_lock(db_url, statement_records): + class Author(Model): + __ferro_table__ = "slog_pass_author" + id: Annotated[int | None, FerroField(primary_key=True)] = None + name: str + + await ferro.connect(db_url) + + await ferro.migrate() + + _assert_lock_lifecycle(statement_records)