Repository navigation
fix(log): panel round 1 for #764 — run-lock statements in the log, pool hooks decided, operation values documented - #773
Conversation
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
left a comment
There was a problem hiding this comment.
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 throughobserve_fetchon the one detachedPgConnectionthe 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, andferro.migrate()). I ran that file against abcb9931build: both Postgres cases fail withassert [] == ['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::droprunscrate::rt::spawn(self.return_to_pool()), which callsafter_releaseon a new task that does not carry the tokio task-local, andmin_connectionsis kept up byspawn_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.rsconsts, theoperation_log(...)literals and builder.py'soperation="exists".subjectis 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 theafter_connecthook is installed only when asearch_pathis configured (src/backend.rs:74). A reader of the Logging section may expect a statement that never runs on a default pool. Fix: "when asearch_pathis configured, theSET search_pathit 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)
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::queryon the lock's detached connection, so aferro migrate uplogged its DDL but not the lock around it. Now the log of a one-migration run on Postgres reads:What changed:
src/backend.rs: newfetch_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 callsobservelike every other path.EngineConnection::fetch_all_sql_unprepared_with_bindsnow shares its Postgres fetch with it (fetch_all_pg_unprepared), so there is still only one fetch.src/run.rs:lock_answersends all three lock statements through that function and reads the boolean they return. The auto-migrate pass uses the sameRunLock, 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 aferro.migrate()pass. Both assert try-lock, then the session probe, then unlock last, every one withoperation == "migrate",subject is None,connection == "default", matching key params,error is None, and all the run'sCREATE TABLErecords falling between the lock and the unlock.RED before the fix:
GREEN:
2 passed.F9: decision (b). Pool hooks are excluded, and the docs say so
The
after_connecthook'sSET search_path TO …and theafter_releaseguard'scurrent_settingcheck 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):
after_releaseon a task it spawns when aPoolConnectiondrops.min_connectionsconnections in background maintenance.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.rsis untouched.F8: every
operationvalue is documentedThe Logging section's
operationrow 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. Thesubjectrow 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:5432was up for every run below (FERRO_POSTGRES_URLset,--db-backends=sqlite,postgres).tests/test_ddl_lock_timeout.pyneeded no change: its assertions filter by step subject, and lock records carry no subject. Nothing intests/test_statement_log.py,src/operations.rsorsrc/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