Skip to content

Commit f479654

Browse files
Haider ZahidCopilot
andcommitted
Address review feedback on caller transaction graph handoff
Resolves all 5 line comments from the automated review of the caller-mode df.start() transaction-handoff fix: 1. HIGH: snapshot-visibility race after pg_xact_status() reports "committed". Postgres can mark a transaction committed before ProcArrayEndTransaction removes it from the running set used by a fresh snapshot, so an immediate re-read could misclassify a valid graph as CommittedMissing. Now checks pg_visible_in_snapshot(origin_xid, pg_current_snapshot()) first and retries until the xid is snapshot-visible before trusting a re-read. 2. HIGH: fixed 2s deadline could livelock a valid graph load (role validation + up to MAX_GRAPH_NODES rows + serialization). Graph loading now uses its own GRAPH_LOAD_QUERY_TIMEOUT (20s client-side) plus Postgres-side statement_timeout/lock_timeout backstops, decoupled from the short TRANSACTION_PROBE_QUERY_TIMEOUT used for cheap visibility and transaction-status probes. 3. HIGH: permanent database errors retried forever. Added SQLSTATE classification (classify_sqlstate/classify_sqlx_error): an allowlist of genuinely transient codes (connection failures, serialization/deadlock, our own statement/lock timeouts, admin-cancel/recovery conflicts) retries as before; everything else (insufficient_privilege, undefined_table, undefined_function, schema/decode errors, ...) now fails the activity immediately with its SQLSTATE embedded. Also added a bounded transient retry budget (MAX_GRAPH_RETRY_ATTEMPTS) tracked independently from the caller-transaction wait counter, so transient DB failures can no longer poll indefinitely even when individually "retryable". 4. MEDIUM: the regression test didn't prove the timeout-retry path executed and could pick an unrelated backend by pid alone. Rewrote 68_long_caller_transaction.sql to identify the graph-probe backend by its exact query text, and to require a strictly later query_start (rather than a different pid, since the management pool may legitimately reuse a connection) for both the post-kill retry and a further, independent timeout-driven retry before the lock is released. Also fixes a real bug found while validating this test: pg_stat_activity's snapshot is cached for the lifetime of the enclosing transaction, so a long-lived DO block must call pg_stat_clear_snapshot() before every poll to observe live backend state. 5. LOW: false OR NULL evaluates to NULL in PL/pgSQL, so a NULL engine_output on failure bypassed the rollback assertions. Added engine_output IS NULL OR ... to both rollback checks. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
1 parent d4f7a3f commit f479654

6 files changed

Lines changed: 485 additions & 39 deletions

File tree

src/activities/load_function_graph.rs

Lines changed: 278 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,25 @@ pub const NAME: &str = "pg_durable::activity::load-function-graph";
2020
/// Transaction-aware graph probe used only by inputs created by the current binary.
2121
pub const TRANSACTION_AWARE_NAME: &str =
2222
"pg_durable::activity::probe-function-graph-transaction-v1";
23+
/// Deadline for cheap visibility/transaction-status probes only (a single
24+
/// primary-key lookup or `pg_xact_status()` call). Graph *loading* uses its own,
25+
/// much longer policy below — see `GRAPH_LOAD_QUERY_TIMEOUT`.
2326
const TRANSACTION_PROBE_QUERY_TIMEOUT: Duration = Duration::from_secs(2);
27+
/// Deadline for the graph-loading path: role validation, fetching up to
28+
/// `MAX_GRAPH_NODES` (10,000) node rows, constructing the graph, and
29+
/// serializing it. Kept well above `TRANSACTION_PROBE_QUERY_TIMEOUT` so a
30+
/// valid-but-large graph load is never mistaken for a stuck probe.
31+
const GRAPH_LOAD_QUERY_TIMEOUT: Duration = Duration::from_secs(20);
32+
/// Postgres-side `statement_timeout` applied while fetching node rows, so a
33+
/// runaway query is cancelled by the server with a proper SQLSTATE instead of
34+
/// relying solely on the client-side `GRAPH_LOAD_QUERY_TIMEOUT` dropping the
35+
/// connection.
36+
const GRAPH_LOAD_STATEMENT_TIMEOUT_MS: u64 = 15_000;
37+
/// Postgres-side `lock_timeout` applied while fetching node rows, so a load
38+
/// blocked behind a conflicting lock on `df.nodes`/`pg_roles` fails fast with
39+
/// `55P03` (classified transient, see `classify_sqlstate`) rather than
40+
/// consuming the whole statement timeout waiting to even start.
41+
const GRAPH_LOAD_LOCK_TIMEOUT_MS: u64 = 5_000;
2442

2543
/// Retry configuration for waiting on uncommitted transactions
2644
pub const MAX_WAIT_SECS: u64 = 5;
@@ -56,6 +74,72 @@ impl LoadGraphError {
5674
}
5775
}
5876

77+
/// Whether a database error observed while probing/loading a graph is worth
78+
/// retrying (bounded, see `MAX_GRAPH_RETRY_ATTEMPTS` in the orchestration) or
79+
/// should fail the workflow immediately.
80+
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
81+
enum ErrorClass {
82+
Transient,
83+
Permanent,
84+
}
85+
86+
/// Classify a Postgres SQLSTATE as transient (worth a bounded retry) or
87+
/// permanent (fail immediately). Deliberately conservative: any code not on
88+
/// the transient allowlist - including codes we don't recognize - is treated
89+
/// as permanent, since silently retrying an unrecognized error forever is
90+
/// exactly the bug class this classification exists to prevent.
91+
fn classify_sqlstate(code: &str) -> ErrorClass {
92+
match code {
93+
// Connection Exception class: transport/connection-level failures
94+
// that are expected to be transient.
95+
"08000" | "08001" | "08003" | "08004" | "08006" | "08007" | "08P01" => {
96+
ErrorClass::Transient
97+
}
98+
// Concurrency conflicts that are expected to clear on retry.
99+
"40001" /* serialization_failure */ | "40P01" /* deadlock_detected */ => {
100+
ErrorClass::Transient
101+
}
102+
// Our own statement/lock timeouts (see GRAPH_LOAD_STATEMENT_TIMEOUT_MS /
103+
// GRAPH_LOAD_LOCK_TIMEOUT_MS): the query was cancelled by policy, not
104+
// because it can never succeed.
105+
"57014" /* query_canceled */ | "55P03" /* lock_not_available */ => ErrorClass::Transient,
106+
// Admin-initiated cancellation / hot-standby conflicts: transient by
107+
// nature (server restart, failover, recovery conflict).
108+
"57P01" | "57P02" | "57P03" => ErrorClass::Transient,
109+
_ => ErrorClass::Permanent,
110+
}
111+
}
112+
113+
/// Extract the SQLSTATE code from a sqlx error, if any.
114+
fn sqlstate_of(error: &sqlx::Error) -> Option<String> {
115+
error
116+
.as_database_error()
117+
.and_then(|db| db.code())
118+
.map(|code| code.into_owned())
119+
}
120+
121+
/// Classify a sqlx error as transient or permanent. Errors without a SQLSTATE
122+
/// (pool exhaustion, IO/TLS/protocol failures - i.e. connection failures that
123+
/// never reached the server) are treated as transient.
124+
fn classify_sqlx_error(error: &sqlx::Error) -> ErrorClass {
125+
match sqlstate_of(error) {
126+
Some(code) => classify_sqlstate(&code),
127+
None => ErrorClass::Transient,
128+
}
129+
}
130+
131+
/// Wrap a sqlx error observed while loading a graph into the appropriately
132+
/// classified `LoadGraphError`, embedding the SQLSTATE (or "unknown") so
133+
/// terminal failures are diagnosable.
134+
fn classified_load_graph_error(operation: &str, error: sqlx::Error) -> LoadGraphError {
135+
let code = sqlstate_of(&error).unwrap_or_else(|| "unknown".to_string());
136+
let message = format!("{operation} failed (SQLSTATE {code}): {error}");
137+
match classify_sqlx_error(&error) {
138+
ErrorClass::Transient => LoadGraphError::Retryable(message),
139+
ErrorClass::Permanent => LoadGraphError::Permanent(message),
140+
}
141+
}
142+
59143
const INSTANCE_QUERY: &str = "SELECT root_node, r.rolname AS submitted_by
60144
FROM df.instances i
61145
LEFT JOIN pg_catalog.pg_roles r ON r.oid = i.submitted_by::oid
@@ -71,6 +155,50 @@ async fn find_visible_instance(
71155
.await
72156
}
73157

158+
/// Fetch a graph's node rows with a real Postgres-side timeout backstop.
159+
///
160+
/// Runs inside its own transaction so `SET LOCAL statement_timeout` /
161+
/// `SET LOCAL lock_timeout` apply only to this read and are automatically
162+
/// discarded when the transaction ends - no risk of leaking a modified
163+
/// timeout onto a pooled connection reused by unrelated work. The read never
164+
/// writes anything, so the transaction is always rolled back regardless of
165+
/// outcome (rollback vs. commit makes no observable difference here; rollback
166+
/// avoids depending on the connection's default transaction characteristics).
167+
async fn fetch_node_rows(
168+
pool: &PgPool,
169+
instance_id: &str,
170+
) -> Result<Vec<sqlx::postgres::PgRow>, sqlx::Error> {
171+
const NODES_QUERY: &str = r#"SELECT n.id, n.node_type, n.query, n.result_name,
172+
n.left_node, n.right_node,
173+
r.rolname AS submitted_by,
174+
n.database
175+
FROM df.nodes n
176+
LEFT JOIN pg_catalog.pg_roles r ON r.oid = n.submitted_by::oid
177+
WHERE n.instance_id = $1"#;
178+
179+
let mut tx = pool.begin().await?;
180+
sqlx::query(&format!(
181+
"SET LOCAL statement_timeout = '{GRAPH_LOAD_STATEMENT_TIMEOUT_MS}ms'"
182+
))
183+
.execute(&mut *tx)
184+
.await?;
185+
sqlx::query(&format!(
186+
"SET LOCAL lock_timeout = '{GRAPH_LOAD_LOCK_TIMEOUT_MS}ms'"
187+
))
188+
.execute(&mut *tx)
189+
.await?;
190+
191+
let rows = sqlx::query(NODES_QUERY)
192+
.bind(instance_id)
193+
.fetch_all(&mut *tx)
194+
.await;
195+
196+
// Best-effort: this is a read-only transaction, so a rollback failure
197+
// (e.g. connection already dropped) doesn't change the outcome we report.
198+
let _ = tx.rollback().await;
199+
rows
200+
}
201+
74202
async fn load_visible_graph(
75203
ctx: &ActivityContext,
76204
pool: &PgPool,
@@ -106,19 +234,9 @@ async fn load_visible_graph(
106234
}
107235
}
108236

109-
let nodes_query = r#"SELECT n.id, n.node_type, n.query, n.result_name,
110-
n.left_node, n.right_node,
111-
r.rolname AS submitted_by,
112-
n.database
113-
FROM df.nodes n
114-
LEFT JOIN pg_catalog.pg_roles r ON r.oid = n.submitted_by::oid
115-
WHERE n.instance_id = $1"#;
116-
117-
let rows = sqlx::query(nodes_query)
118-
.bind(&instance_id)
119-
.fetch_all(pool)
237+
let rows = fetch_node_rows(pool, &instance_id)
120238
.await
121-
.map_err(|e| LoadGraphError::Retryable(format!("Failed to load function nodes: {e}")))?;
239+
.map_err(|e| classified_load_graph_error("Failed to load function nodes", e))?;
122240

123241
let mut nodes = std::collections::BTreeMap::new();
124242
for row in rows {
@@ -224,6 +342,52 @@ fn retry_probe(
224342
serialize_probe(&TransactionGraphProbe::Retry)
225343
}
226344

345+
/// Route a sqlx error encountered while probing (visibility/transaction-status
346+
/// checks) through classification: transient errors become a bounded `Retry`
347+
/// probe result, permanent errors fail the activity immediately with the
348+
/// SQLSTATE embedded so the workflow doesn't poll forever on an unrecoverable
349+
/// condition (e.g. insufficient_privilege, undefined_table).
350+
fn probe_error_outcome(
351+
ctx: &ActivityContext,
352+
operation: &str,
353+
instance_id: &str,
354+
error: sqlx::Error,
355+
) -> Result<String, String> {
356+
match classify_sqlx_error(&error) {
357+
ErrorClass::Transient => retry_probe(ctx, operation, instance_id, error),
358+
ErrorClass::Permanent => {
359+
let code = sqlstate_of(&error).unwrap_or_else(|| "unknown".to_string());
360+
Err(format!(
361+
"Instance {instance_id}: {operation} failed permanently (SQLSTATE {code}): {error}"
362+
))
363+
}
364+
}
365+
}
366+
367+
/// Decision point for the exact race window this handles: PostgreSQL can
368+
/// record a transaction as committed before `ProcArrayEndTransaction` removes
369+
/// it from the running-transactions set used to build a fresh snapshot. In
370+
/// that window, a graph re-read can spuriously return no rows even though the
371+
/// transaction is genuinely committed and the graph exists. Extracted as a
372+
/// pure function so the decision itself has direct unit coverage.
373+
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
374+
enum CommittedProbeStep {
375+
/// The origin xid is committed but not yet snapshot-visible: retry
376+
/// (bounded) instead of trusting a re-read.
377+
AwaitSnapshotVisibility,
378+
/// The origin xid is committed and snapshot-visible: a re-read that finds
379+
/// no graph can be trusted as genuine `CommittedMissing`.
380+
ReadyToReread,
381+
}
382+
383+
fn committed_probe_step(snapshot_visible: bool) -> CommittedProbeStep {
384+
if snapshot_visible {
385+
CommittedProbeStep::ReadyToReread
386+
} else {
387+
CommittedProbeStep::AwaitSnapshotVisibility
388+
}
389+
}
390+
227391
/// Probe graph visibility without pinning an activity task while the caller's
228392
/// transaction remains open. The orchestration schedules a durable timer and
229393
/// invokes this single-shot activity again when the xid is still in progress.
@@ -266,7 +430,7 @@ pub async fn probe_transaction(
266430
match visible {
267431
Ok(Some(row)) => {
268432
let loaded = match tokio::time::timeout(
269-
TRANSACTION_PROBE_QUERY_TIMEOUT,
433+
GRAPH_LOAD_QUERY_TIMEOUT,
270434
load_visible_graph(&ctx, pool.as_ref(), input.instance_id.clone(), row),
271435
)
272436
.await
@@ -277,7 +441,7 @@ pub async fn probe_transaction(
277441
&ctx,
278442
"graph load",
279443
&input.instance_id,
280-
"timed out after 2s",
444+
format!("timed out after {}s", GRAPH_LOAD_QUERY_TIMEOUT.as_secs()),
281445
);
282446
}
283447
};
@@ -291,7 +455,7 @@ pub async fn probe_transaction(
291455
}
292456
Ok(None) => {}
293457
Err(e) => {
294-
return retry_probe(&ctx, "graph visibility check", &input.instance_id, e);
458+
return probe_error_outcome(&ctx, "graph visibility check", &input.instance_id, e);
295459
}
296460
}
297461

@@ -305,7 +469,7 @@ pub async fn probe_transaction(
305469
let transaction_status: Option<String> = match transaction_status_query {
306470
Ok(Ok(status)) => status,
307471
Ok(Err(e)) => {
308-
return retry_probe(&ctx, "origin transaction check", &input.instance_id, e);
472+
return probe_error_outcome(&ctx, "origin transaction check", &input.instance_id, e);
309473
}
310474
Err(_) => {
311475
return retry_probe(
@@ -321,9 +485,56 @@ pub async fn probe_transaction(
321485
Some("in progress") => TransactionGraphProbe::InProgress,
322486
Some("aborted") => TransactionGraphProbe::Aborted,
323487
Some("committed") => {
488+
// pg_xact_status() can report "committed" before
489+
// ProcArrayEndTransaction removes the xid from the running set
490+
// used to build a fresh snapshot. Check snapshot visibility
491+
// explicitly before trusting a re-read as proof the graph is
492+
// absent - otherwise a valid committed graph can be permanently
493+
// misclassified as CommittedMissing during this narrow window.
494+
let snapshot_visible_query = tokio::time::timeout(
495+
TRANSACTION_PROBE_QUERY_TIMEOUT,
496+
sqlx::query_scalar::<_, bool>(
497+
"SELECT pg_catalog.pg_visible_in_snapshot($1::text::xid8, pg_catalog.pg_current_snapshot())",
498+
)
499+
.bind(&input.origin_xid)
500+
.fetch_one(pool.as_ref()),
501+
)
502+
.await;
503+
let snapshot_visible = match snapshot_visible_query {
504+
Ok(Ok(visible)) => visible,
505+
Ok(Err(e)) => {
506+
return probe_error_outcome(
507+
&ctx,
508+
"post-commit snapshot visibility check",
509+
&input.instance_id,
510+
e,
511+
);
512+
}
513+
Err(_) => {
514+
return retry_probe(
515+
&ctx,
516+
"post-commit snapshot visibility check",
517+
&input.instance_id,
518+
"timed out after 2s",
519+
);
520+
}
521+
};
522+
523+
if committed_probe_step(snapshot_visible) == CommittedProbeStep::AwaitSnapshotVisibility
524+
{
525+
return retry_probe(
526+
&ctx,
527+
"post-commit snapshot visibility",
528+
&input.instance_id,
529+
"origin transaction committed but not yet snapshot-visible",
530+
);
531+
}
532+
324533
// The status and graph reads use separate READ COMMITTED statements.
325534
// Re-read once after observing commit so a commit between the first
326535
// graph query and pg_xact_status cannot be misclassified as missing.
536+
// Snapshot visibility is now confirmed above, so a `None` here is a
537+
// genuine CommittedMissing, not a visibility race.
327538
let visible = match tokio::time::timeout(
328539
TRANSACTION_PROBE_QUERY_TIMEOUT,
329540
find_visible_instance(pool.as_ref(), &input.instance_id),
@@ -343,7 +554,7 @@ pub async fn probe_transaction(
343554
match visible {
344555
Ok(Some(row)) => {
345556
let loaded = match tokio::time::timeout(
346-
TRANSACTION_PROBE_QUERY_TIMEOUT,
557+
GRAPH_LOAD_QUERY_TIMEOUT,
347558
load_visible_graph(&ctx, pool.as_ref(), input.instance_id.clone(), row),
348559
)
349560
.await
@@ -354,7 +565,7 @@ pub async fn probe_transaction(
354565
&ctx,
355566
"post-commit graph load",
356567
&input.instance_id,
357-
"timed out after 2s",
568+
format!("timed out after {}s", GRAPH_LOAD_QUERY_TIMEOUT.as_secs()),
358569
);
359570
}
360571
};
@@ -373,7 +584,7 @@ pub async fn probe_transaction(
373584
}
374585
Ok(None) => TransactionGraphProbe::CommittedMissing,
375586
Err(e) => {
376-
return retry_probe(
587+
return probe_error_outcome(
377588
&ctx,
378589
"post-commit graph visibility check",
379590
&input.instance_id,
@@ -435,4 +646,52 @@ mod tests {
435646
r#"{"state":"committed_missing"}"#
436647
);
437648
}
649+
650+
#[test]
651+
fn committed_probe_step_awaits_snapshot_visibility_until_confirmed() {
652+
// The exact race this covers: pg_xact_status() already reports
653+
// "committed" but the xid isn't snapshot-visible yet - must not be
654+
// treated as ready to re-read (that would risk a spurious
655+
// CommittedMissing classification for a genuinely committed graph).
656+
assert_eq!(
657+
committed_probe_step(false),
658+
CommittedProbeStep::AwaitSnapshotVisibility
659+
);
660+
assert_eq!(
661+
committed_probe_step(true),
662+
CommittedProbeStep::ReadyToReread
663+
);
664+
}
665+
666+
#[test]
667+
fn classify_sqlstate_allows_connection_and_our_own_timeout_codes() {
668+
for code in [
669+
"08000", "08001", "08003", "08004", "08006", "08007", "08P01", "40001", "40P01",
670+
"57014", "55P03", "57P01", "57P02", "57P03",
671+
] {
672+
assert_eq!(
673+
classify_sqlstate(code),
674+
ErrorClass::Transient,
675+
"expected {code} to classify as transient"
676+
);
677+
}
678+
}
679+
680+
#[test]
681+
fn classify_sqlstate_treats_privilege_and_schema_errors_as_permanent() {
682+
for code in ["42501", "42883", "42P01", "22P02", "23505"] {
683+
assert_eq!(
684+
classify_sqlstate(code),
685+
ErrorClass::Permanent,
686+
"expected {code} to classify as permanent"
687+
);
688+
}
689+
}
690+
691+
#[test]
692+
fn classify_sqlstate_defaults_unknown_codes_to_permanent() {
693+
// Deliberate: an unrecognized SQLSTATE must not be silently retried
694+
// forever - that's exactly the bug class being fixed.
695+
assert_eq!(classify_sqlstate("XXUNK"), ErrorClass::Permanent);
696+
}
438697
}

0 commit comments

Comments
 (0)