Skip to content

fix(log): panel round 1 for #764 — run-lock statements in the log, pool hooks decided, operation values documented - #773

Merged
0x054 merged 2 commits into
feat/700-sql-inspectionfrom
sdd/764-fix-panel-round-1
Oct 21, 2026
Merged

0x054 merged 2 commits into
feat/700-sql-inspectionfrom
sdd/764-fix-panel-round-1

Conversation

@0x054

@0x054 0x054 commented Oct 21, 2026

Copy link
Copy Markdown
Contributor

Panel round 1 on PR #771, the three findings in files #764 owned: F3, F9 and F8.

F3: the run lock's statements are in the log

On Postgres a run takes its lock, checks it on its own session and releases it with three statements. They went out through raw sqlx::query on the lock's detached connection, so a ferro migrate up logged its DDL but not the lock around it. Now the log of a one-migration run on Postgres reads:

SELECT pg_try_advisory_lock($1) params=(…,)
SELECT EXISTS (SELECT 1 FROM pg_locks … AND pid = pg_backend_pid()) params=(…, …)
CREATE TABLE "slog_author" (…) params=()
…
SELECT pg_advisory_unlock($1) params=(…,)

What changed:

  • src/backend.rs: new fetch_all_detached_pg_unprepared(conn: &mut PgConnection, sql, values). It is the engine's fetch layer for a connection the pool no longer owns, and it calls observe like every other path. EngineConnection::fetch_all_sql_unprepared_with_binds now shares its Postgres fetch with it (fetch_all_pg_unprepared), so there is still only one fetch.
  • src/run.rs: lock_answer sends all three lock statements through that function and reads the boolean they return. The auto-migrate pass uses the same RunLock, so its lock statements are now records as well.

Tests: tests/test_statement_log_run.py (Postgres only). It covers a migration run through the harness and a ferro.migrate() pass. Both assert try-lock, then the session probe, then unlock last, every one with operation == "migrate", subject is None, connection == "default", matching key params, error is None, and all the run's CREATE TABLE records falling between the lock and the unlock.

RED before the fix:

$ uv run --no-sync pytest tests/test_statement_log_run.py -q --no-cov -p no:cacheprovider --db-backends=sqlite,postgres
E       AssertionError: assert [] == ['SELECT pg_try_advisory_lock($1)']
FAILED tests/test_statement_log_run.py::test_a_run_logs_taking_checking_and_releasing_its_lock[postgres]
FAILED tests/test_statement_log_run.py::test_the_reconciliation_pass_logs_its_lock[postgres]
2 failed

GREEN: 2 passed.

F9: decision (b). Pool hooks are excluded, and the docs say so

The after_connect hook's SET search_path TO … and the after_release guard's current_setting check are left out of the log. The exclusion is now written down in the Connections guide's Logging section and in a dated amendment at the end of ADR-0057 (a separate paragraph, so it does not touch fix-765's redaction amendment).

Why not (a):

  • sqlx 0.8 runs after_release on a task it spawns when a PoolConnection drops.
  • It opens min_connections connections in background maintenance.
  • A task-local scope would therefore reach only the connects an operation happens to wait on.
  • Logging the rest would need sql_log::enabled (a GIL take) on every connection open and every guarded release. That is the per-pool-event cost the finding says (a) must not have.

src/sql_log.rs is untouched.

F8: every operation value is documented

The Logging section's operation row now points to a second short table that gives each value one phrase: fetch, count/exists, save, bulk_create, update/delete, m2m_add/m2m_remove/m2m_clear, raw, transaction, settings, catalog, migrate (run-lock statements included). I used a separate table because one cell holding thirteen values would not stay readable. The subject row was already in the table (F10). The section still fits on one screen, and no Python example was touched, so I-7, I-8 and I-14 are unaffected.

Verify

Postgres at localhost:5432 was up for every run below (FERRO_POSTGRES_URL set, --db-backends=sqlite,postgres).

$ uv run maturin develop                                   -> Installed ferro-orm-0.25.0
$ uv run --no-sync pytest tests/test_statement_log.py tests/test_ddl_lock_timeout.py tests/test_migrations_testing_harness.py tests/test_statement_log_run.py tests/test_run_lock.py -q --no-cov -p no:cacheprovider --db-backends=sqlite,postgres
164 passed, 25 skipped
$ uv run --no-sync pytest tests -q --no-cov -p no:cacheprovider --db-backends=sqlite,postgres -k "cli or auto_migrate or create_tables or docs or lock"
1068 passed, 29 skipped, 3859 deselected
$ cargo test --no-default-features --features testing      -> 382 passed; 0 failed
$ uv run --no-sync ruff check src/ferro tests              -> All checks passed!
$ cargo fmt --check; cargo clippy                          -> clean

tests/test_ddl_lock_timeout.py needed no change: its assertions filter by step subject, and lock records carry no subject. Nothing in tests/test_statement_log.py, src/operations.rs or src/ferro/** needed to change.

Interfaces changed: none. One function was added, backend::fetch_all_detached_pg_unprepared, and no existing signature changed.

Verify block corrected: no

Part of #700 (panel round 1 on PR #771)

🤖 Generated with Claude Code
https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP

0x054 and others added 2 commits October 21, 2026 08:20
On Postgres a run takes, checks and releases its lock with
`pg_try_advisory_lock`, a held-by-this-session probe and
`pg_advisory_unlock` on a detached connection. They went out through raw
`sqlx::query` and never reached `sql_log::observe`, so the log of a
`ferro migrate up` or an auto-migrate pass had holes around its DDL.

They now go through `backend::fetch_all_detached_pg_unprepared`, the
engine's fetch layer for a connection the pool no longer owns, and are
records under the run's `migrate` scope. Pinned by
tests/test_statement_log_run.py for a migration run and for the pass.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP
…ot logged

The Connections guide's Logging section listed `operation` as only
"migrate"; it now lists every value the statement log writes, one phrase
each. A Postgres pool's own `SET search_path` and settings-release check
run outside any operation and are not in the log: stated in the guide and
in a dated amendment to ADR-0057.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Hb9U9A7Zu9ypdHTsDvdScP

@0x054 0x054 left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Spec: PASS

Spec for this slice: panel findings F3, F9 and F8 from #771 (comment). The PR carries no Closes #N; #764 is already closed and this is a panel fix slice (Part of #700), so that is accepted and not a failure.

  • F3 · ADDRESSED · src/run.rs:663-673 (lock_answer), src/run.rs:736, src/run.rs:845, src/run.rs:872, src/backend.rs:1025-1033 (fetch_all_detached_pg_unprepared) at 62b07fe · all three lock statements go through observe_fetch on the one detached PgConnection the lock was taken on (&mut conn / conn.as_mut()); none of them touches a pooled connection. Pinned by tests/test_statement_log_run.py (migration run through the harness, and ferro.migrate()). I ran that file against a bcb9931 build: both Postgres cases fail with assert [] == ['SELECT pg_try_advisory_lock($1)']. They pass at 62b07fe.
  • F9 · ADDRESSED (decision b) · docs/adr/0057-…md:40-42, docs/pages/guide/connections.md:265 at 62b07fe · the exclusion is stated in both places, and the stated reason holds. In sqlx-core 0.8.6, PoolConnection::drop runs crate::rt::spawn(self.return_to_pool()), which calls after_release on a new task that does not carry the tokio task-local, and min_connections is kept up by spawn_maintenance_tasks (pool/connection.rs:200-208, 289; pool/inner.rs:70, 396-420). One precision gap, listed under Quality as Minor.
  • F8 · ADDRESSED · docs/pages/guide/connections.md:245, :251-264 at 62b07fe · the table lists all 15 values the code emits (fetch, count, exists, save, bulk_create, update, delete, m2m_add/remove/clear, raw, transaction, settings, catalog, migrate). I checked it against the sql_log.rs consts, the operation_log(...) literals and builder.py's operation="exists". subject is in the attribute table.
    Cannot verify: none

Quality: PASS

  • Minor · docs/pages/guide/connections.md:265 and docs/adr/0057-…md:42 at 62b07fe · both say the pool runs SET search_path "on each new connection", but the after_connect hook is installed only when a search_path is configured (src/backend.rs:74). A reader of the Logging section may expect a statement that never runs on a default pool. Fix: "when a search_path is configured, the SET search_path it runs on each new connection".

Depth check: fetch_all_detached_pg_unprepared and lock_answer both fired none of the four questions. The first is the observe seam for a connection the pool no longer owns, and its fetch body is shared with EngineConnection, so the fetch is not duplicated. The second hides the row decode from three callers. The tests assert at the public seam (ferro.sql records).
Checked: lock safety on emitter error. observe stores the error in the scope and returns, so lock_answer still answers. In acquire_or, a raising handler cannot skip the timeout close() or the verify → release path. In release, the unlock result is discarded and conn.close() always runs. The pass (src/migrate.rs:790-808) acquires and releases inside one future, so an emitter error surfaces only after release() has run. probe_lost_the_session still sees the raw sqlx::Error, because fetch_all passes it through unchanged. Bind types are unchanged (key, classid and objid are i64, bound as EngineBindValue::I64).
Out-of-scope observation (pre-existing, does not block): if a ferro.sql handler raises during LockScope.__aenter__ (src/migrations_ffi.rs:1037-1068), the lock is still taken and stored in entered, but __aenter__ raises, so __aexit__ never runs. The lock then holds until the LockScope object is dropped and the detached socket closes. This already happened at bcb9931 through the governed_schema record, so this PR did not introduce it.

Verify: PR head 62b07fe passed (maturin develop; #764 block files plus tests/test_statement_log_run.py and tests/test_run_lock.py: 164 passed, 25 skipped; -k "cli or auto_migrate or create_tables": 566 passed, 2 skipped; cargo test --no-default-features --features testing: 382 passed; ruff check src/ferro tests clean; all pytest with --db-backends=sqlite,postgres and Postgres accepting connections at localhost:5432)
Trial merge: not run (base unchanged: feat/700-sql-inspection is still at bcb9931)

@0x054
0x054 merged commit 2b96072 into feat/700-sql-inspection Oct 21, 2026
6 checks passed
@0x054
0x054 deleted the sdd/764-fix-panel-round-1 branch October 21, 2026 12:32
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant