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