diff --git a/CHANGELOG.md b/CHANGELOG.md index 5c7713127..6ff1f00f5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ Notable changes between releases. Detailed migration notes for storage transitio - The schema stays at v40. `awa migrate` applies one new repeatable patch, `replica_identity`. Unlike the earlier 0.6 patches it takes table locks: `ACCESS EXCLUSIVE` on each table it changes (`awa.admin_dirty_queue_marks`, `awa.admin_dirty_kind_marks`, `awa.job_unique_claims` and each `queue_terminal_count_deltas` table and partition), plus `SHARE` on `idx_awa_jobs_unique`, held until the patch commits, which is milliseconds once granted. Each lock wait is bounded by the session's `lock_timeout`, or 300 ms when none is set; a timeout fails the patch with `55P03` and changes nothing, so run `awa migrate` again. A re-run after success takes no lock. External migration runners apply `R__replica_identity.sql` after `V40` and after the other `R__` scripts, as the owner of the awa and queue-storage tables. 0.6.17 binaries run unchanged on the patched schema, so binaries and the patch can roll in either order. See the [upgrade guide](docs/upgrade-0.6.17-to-0.6.18.md). +### Added + +- Python `Job.run_lease` exposes the attempt's lease identifier, read-only, for diagnostic correlation. + ### Changed - Ring prune truncates only the children of the sealed slot that hold storage (0.6 port of #512). Queue, lease and claim prune take the same locks on every child of the slot, in the same order, as in 0.6.17, then `TRUNCATE` only the children with heap, TOAST, free-space-map or visibility-map pages, or index pages beyond an empty btree, GiST or BRIN index. A child that never held a row keeps its relfilenode, so a prune no longer swaps relfilenodes and writes WAL and catalog rows for empty partitions, such as the receipt children of a schema without receipts. A child emptied by `DELETE` and `VACUUM` that kept expanded indexes or TOAST is still truncated. The empty-slot fast path is unchanged. No configuration or schema change. diff --git a/awa-python/python/awa/_awa.pyi b/awa-python/python/awa/_awa.pyi index 4618749a8..13e8be0da 100644 --- a/awa-python/python/awa/_awa.pyi +++ b/awa-python/python/awa/_awa.pyi @@ -112,6 +112,8 @@ class Job(Generic[T]): @property def attempt(self) -> int: ... @property + def run_lease(self) -> int: ... + @property def max_attempts(self) -> int: ... @property def tags(self) -> list[str]: ... diff --git a/awa-python/src/job.rs b/awa-python/src/job.rs index 79967803f..efea852c4 100644 --- a/awa-python/src/job.rs +++ b/awa-python/src/job.rs @@ -86,6 +86,7 @@ pub struct PyJob { pub priority: i16, #[pyo3(get)] pub attempt: i16, + #[pyo3(get)] pub run_lease: i64, #[pyo3(get)] pub max_attempts: i16, diff --git a/awa/tests/bulk_rescue_test.rs b/awa/tests/bulk_rescue_test.rs index 89f41e5e5..6a37b986c 100644 --- a/awa/tests/bulk_rescue_test.rs +++ b/awa/tests/bulk_rescue_test.rs @@ -15,7 +15,7 @@ use opentelemetry_sdk::metrics::{InMemoryMetricExporter, SdkMeterProvider}; use serde::{Deserialize, Serialize}; use sqlx::postgres::{PgConnection, PgPoolOptions}; use sqlx::{Connection, PgPool}; -use std::collections::HashMap; +use std::collections::{HashMap, HashSet}; use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, Mutex}; use std::time::{Duration, Instant}; @@ -35,6 +35,8 @@ static BACKLOG_TEST: tokio::sync::Mutex<()> = tokio::sync::Mutex::const_new(()); /// What each run of a job saw, by job id. type RunsByJob = HashMap>; +/// The `(job_id, run_lease)` of every attempt a handler ran. +type HandledAttempts = Arc>>; #[derive(Debug, Serialize, Deserialize, JobArgs)] struct AbandonedJob { @@ -412,6 +414,59 @@ impl Drop for BulkRescueDatabase { } } +/// Installs the persona soak's completion witness: triggers that copy every +/// committed completion, receipt or materialized, into a plain table that +/// prune never touches. +async fn install_completion_witness(pool: &PgPool) { + sqlx::raw_sql(&include_str!("persona_soak/gate_proof.sql").replace("__SCHEMA__", "awa")) + .execute(pool) + .await + .expect("install completion witness"); +} + +/// Committed completions of `queue` as `(job_id, run_lease, attempt)`, one row +/// per completion written, so a repeated completion shows up twice. +async fn witnessed_completions(pool: &PgPool, queue: &str) -> Vec<(i64, i64, i16)> { + sqlx::query_as( + "SELECT job_id, run_lease, attempt FROM public.awa_soak_completed_inserts + WHERE queue = $1 ORDER BY job_id, run_lease", + ) + .bind(queue) + .fetch_all(pool) + .await + .expect("witnessed completions") +} + +/// Asserts the witnessed completions are exactly the attempts the handlers +/// returned from, once each and all on `attempt`, and returns their job ids. +fn assert_completed_exactly( + witnessed: &[(i64, i64, i16)], + returned: &HashSet<(i64, i64)>, + attempt: i16, +) -> HashSet { + let pairs: HashSet<(i64, i64)> = witnessed + .iter() + .map(|(id, lease, _)| (*id, *lease)) + .collect(); + let ids: HashSet = witnessed.iter().map(|(id, _, _)| *id).collect(); + assert_eq!(witnessed.len(), pairs.len(), "an attempt completed twice"); + assert_eq!(witnessed.len(), ids.len(), "a job completed more than once"); + assert_eq!( + &pairs, returned, + "committed completions differ from handler returns" + ); + let other_attempts: Vec<_> = witnessed + .iter() + .filter(|(_, _, observed)| *observed != attempt) + .take(5) + .collect(); + assert!( + other_attempts.is_empty(), + "completed on an attempt other than {attempt}: {other_attempts:?}" + ); + ids +} + /// A client on its own Tokio runtime, so it can be killed the way SIGKILL /// would: every task is dropped mid-flight, no shutdown runs, and its /// connections close with their transactions rolled back. @@ -495,6 +550,7 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { let db = BulkRescueDatabase::create().await; let pool = db.pool().clone(); + install_completion_witness(&pool).await; let store = QueueStorage::new(QueueStorageConfig::default()).expect("queue storage"); let claim_slots = store.claim_slot_count() as i64; @@ -512,10 +568,12 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { .await .expect("live pool"); let live_runs: Arc>> = Arc::default(); + let live_attempts: HandledAttempts = Arc::default(); // The live runtime leads maintenance, so it sees every rescue. let rescues: Arc>> = Arc::default(); let live = { let live_runs = live_runs.clone(); + let live_attempts = live_attempts.clone(); let live_rescues = rescues.clone(); let abandoned_rescues = rescues.clone(); queue_storage_builder(&live_pool, staleness, heartbeat_interval) @@ -562,6 +620,10 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { .entry(ctx.job.id) .or_default() .push(ctx.job.attempt); + live_attempts + .lock() + .expect("live attempts") + .insert((ctx.job.id, ctx.job.run_lease)); async move { tokio::time::sleep(Duration::from_millis(job.hold_ms)).await; Ok(JobResult::Completed) @@ -760,6 +822,7 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { // A fresh runtime runs every retried job exactly once, on its second attempt. let recovered: Arc>> = Arc::default(); + let recovered_attempts: HandledAttempts = Arc::default(); let recovery_pool = PgPoolOptions::new() .max_connections(20) .connect(&db.url()) @@ -767,6 +830,7 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { .expect("recovery pool"); let recovery = { let recovered = recovered.clone(); + let recovered_attempts = recovered_attempts.clone(); queue_storage_builder(&recovery_pool, staleness, heartbeat_interval) .queue( ABANDONED_QUEUE, @@ -795,6 +859,10 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { .entry(ctx.job.id) .or_default() .push((ctx.job.attempt, rescue_recorded)); + recovered_attempts + .lock() + .expect("recovered attempts") + .insert((ctx.job.id, ctx.job.run_lease)); async { Ok(JobResult::Completed) } }) .build() @@ -815,6 +883,15 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { || async { running(&pool, &store, ABANDONED_QUEUE).await == 0 && waiting_retry_counts(&pool, ABANDONED_QUEUE).await == (0, 0) + && count( + &pool, + format!( + "SELECT count(*) FROM public.awa_soak_completed_inserts + WHERE queue = '{ABANDONED_QUEUE}'" + ), + ) + .await + >= ABANDONED - exhausted }, ) .await; @@ -865,6 +942,48 @@ async fn rescue_drains_an_abandoned_backlog_without_rescuing_live_claims() { "neither live nor recovered attempts may be rescued: {unexpected:?}" ); } + + // Prune has had time to drop many of these completions, so the witness, + // not the queue tables, shows which attempts committed. + let recovered_ids = assert_completed_exactly( + &witnessed_completions(&pool, ABANDONED_QUEUE).await, + &recovered_attempts.lock().expect("recovered attempts"), + 2, + ); + let live_ids = assert_completed_exactly( + &witnessed_completions(&pool, LIVE_QUEUE).await, + &live_attempts.lock().expect("live attempts"), + 1, + ); + assert_eq!( + live_ids.len(), + produced, + "every live job committed its completion" + ); + let dead_lettered: HashSet = sqlx::query_scalar( + "SELECT job_id FROM awa.dlq_entries WHERE queue = $1 AND dlq_reason = 'heartbeat_stale'", + ) + .bind(ABANDONED_QUEUE) + .fetch_all(&pool) + .await + .expect("dead-lettered abandoned jobs") + .into_iter() + .collect(); + assert!( + dead_lettered.is_disjoint(&recovered_ids), + "a job was both dead-lettered and completed" + ); + let abandoned_outcomes: HashSet = dead_lettered.union(&recovered_ids).copied().collect(); + assert_eq!( + abandoned_outcomes, + rescues + .lock() + .expect("rescues") + .keys() + .copied() + .collect::>(), + "every rescued job ends exactly once, dead-lettered or completed" + ); let live_runs = live_runs.lock().expect("live runs"); assert_eq!(live_runs.len(), produced, "every live job ran"); let rerun: Vec<_> = live_runs diff --git a/awa/tests/operation_lock_footprint_test.rs b/awa/tests/operation_lock_footprint_test.rs new file mode 100644 index 000000000..e4a934721 --- /dev/null +++ b/awa/tests/operation_lock_footprint_test.rs @@ -0,0 +1,619 @@ +//! Opt-in diagnostics in disposable databases: a controlled operation fixture +//! with API-only timing and backend identity markers, and the query plan of a +//! 10,000-job bulk failed-to-DLQ move. Maintenance is disabled; the fixture +//! uses default ring sizes. + +use awa::model::{ + admin, migrations, InsertOpts, InsertParams, JobState, QueueStorage, QueueStorageConfig, +}; +use sqlx::postgres::{PgConnectOptions, PgPoolOptions}; +use sqlx::PgPool; +use std::{collections::BTreeSet, str::FromStr, time::Duration}; + +type Error = Box; +fn check(ok: bool, message: &str) -> Result<(), Error> { + if ok { + Ok(()) + } else { + Err(message.to_owned().into()) + } +} +async fn pool(options: &PgConnectOptions, app: &str) -> Result { + PgPoolOptions::new() + .max_connections(1) + .connect_with(options.clone().application_name(app)) + .await +} + +fn operation_persona(operation: &str) -> &'static str { + if operation.starts_with("claim_") || operation.starts_with("complete_") { + "worker" + } else if operation.starts_with("get_") || operation.starts_with("terminal_") { + "support" + } else { + "watcher" + } +} +fn clock_ns() -> u128 { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap() + .as_nanos() +} +async fn operation_identity(pool: &PgPool) -> Result { + Ok(sqlx::query_scalar("SELECT jsonb_build_object('pid',pid,'backend_start',backend_start::text,'datid',datid,'application_name',application_name,'server_at',clock_timestamp()) FROM pg_stat_activity WHERE pid=pg_backend_pid()") + .fetch_one(pool).await?) +} +async fn measured( + pool: &PgPool, + app: &str, + api: F, + summarize: S, +) -> Result, Error> +where + E: std::fmt::Display, + F: std::future::Future>, + S: FnOnce(&Result) -> serde_json::Value, +{ + // This autocommit bootstrap finishes before OP_START. No measured API + // owns an outer connection lease or transaction. + let identity = operation_identity(pool).await?; + check( + identity["application_name"] == app, + "operation pool application differs", + )?; + let operation = app + .strip_prefix("awa_read_footprint_") + .ok_or("unregistered operation application")?; + let operation_id = uuid::Uuid::new_v4().to_string(); + let persona = operation_persona(operation); + let start_ns = clock_ns(); + eprintln!( + "OP_START {}", + serde_json::json!({"operation_id":operation_id,"operation":operation,"persona":persona,"application_name":app,"identity":identity,"client_ns":start_ns,"boundary":"API-only; bootstrap completed"}) + ); + let start = std::time::Instant::now(); + let result = api.await; + let elapsed_us = start.elapsed().as_micros(); + let end_ns = clock_ns(); + let outcome = if result.is_ok() { + "api_ok" + } else { + "api_error" + }; + let error = result.as_ref().err().map(ToString::to_string); + eprintln!( + "OP_END {}", + serde_json::json!({"operation_id":operation_id,"operation":operation,"persona":persona,"application_name":app,"identity":identity,"client_ns":end_ns,"started_client_ns":start_ns,"elapsed_us":elapsed_us,"outcome":outcome,"error":error,"result":summarize(&result),"checks":"original fixture assertions and PASS marker required separately"}) + ); + // Identity verification also runs outside the measured interval. A + // reconnect invalidates this operation even if the API returned success. + let after = operation_identity(pool).await?; + for key in ["pid", "backend_start", "datid", "application_name"] { + check( + after[key] == identity[key], + "operation backend changed during API", + )?; + } + Ok(result) +} + +async fn point( + store: &QueueStorage, + options: &PgConnectOptions, + app: &str, + id: i64, + state: JobState, +) -> Result<(), Error> { + let pool = pool(options, app).await?; + let result = measured(&pool, app, store.load_job(&pool, id), |r| serde_json::json!({ + "returned_rows":r.as_ref().ok().map(|v|usize::from(v.is_some())), + "rows":r.as_ref().ok().and_then(|v|v.as_ref()).map(|j|serde_json::json!({"id":j.id,"state":format!("{:?}",j.state),"args":j.args})) + })).await?; + pool.close().await; + let job = result?.ok_or("point read omitted job")?; + check(job.state == state, "point-read state differs")?; + eprintln!("READ_FOOTPRINT_API {app} job={id} state={state:?} PASS"); + Ok(()) +} +async fn page( + options: &PgConnectOptions, + app: &str, + queue: Option<&str>, + state: Option, + expected: Option, +) -> Result<(), Error> { + let pool = pool(options, app).await?; + let result = measured(&pool, app, admin::list_jobs( + &pool, + &admin::ListJobsFilter { + queue: queue.map(str::to_owned), + state, + limit: Some(20), + ..Default::default() + }, + ), |r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len()),"rows":r.as_ref().ok().map(|v|v.iter().map(|j|serde_json::json!({"id":j.id,"state":format!("{:?}",j.state),"args":j.args})).collect::>())})).await?; + pool.close().await; + let rows = result?; + let ids: BTreeSet<_> = rows.iter().map(|job| job.id).collect(); + check(ids.len() == rows.len(), "list page duplicated an identity")?; + if let Some(queue) = queue { + check( + rows.iter().all(|job| job.queue == queue), + "list page escaped queue scope", + )?; + } + check(rows.len() <= 20, "list page exceeded requested limit")?; + if let Some(expected) = expected { + check( + rows.len() == expected, + "list page has unexpected cardinality", + )?; + } + let states: Vec<_> = rows + .iter() + .map(|job| (job.id, format!("{:?}", job.state))) + .collect(); + eprintln!( + "READ_FOOTPRINT_API {app} page_limit=20 actual={} rows={} PASS", + rows.len(), + serde_json::to_string(&states)? + ); + Ok(()) +} + +async fn dashboards(options: &PgConnectOptions) -> Result<(), Error> { + // Fresh single-connection pools keep each API attributable. Every public + // call finishes before close; there is no outer connection/transaction lease. + let app = "awa_read_footprint_state_counts"; + let pool = pool(options, app).await?; + let result = measured( + &pool, + app, + admin::state_counts(&pool), + |r| serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.counts.len())}), + ) + .await?; + pool.close().await; + let rows = result?; + check( + rows.counts.values().sum::() == 40, + "state counts lost seeded work", + )?; + eprintln!( + "READ_FOOTPRINT_API {app} result={} PASS", + serde_json::to_string(&rows)? + ); + + let app = "awa_read_footprint_queue_overviews"; + let queue_pool = self::pool(options, app).await?; + let result = measured( + &queue_pool, + app, + admin::queue_overviews(&queue_pool), + |r| serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len())}), + ) + .await?; + queue_pool.close().await; + let rows = result?; + let queues: BTreeSet<_> = rows.iter().map(|row| &row.queue).collect(); + check( + queues.len() == rows.len(), + "queue overview duplicated a queue", + )?; + check( + rows.iter() + .filter(|row| row.queue.starts_with("footprint_")) + .map(|row| row.total_queued) + .sum::() + == 40, + "queue overview lost seeded work", + )?; + eprintln!( + "READ_FOOTPRINT_API {app} result={} PASS", + serde_json::to_string(&rows)? + ); + + let app = "awa_read_footprint_kind_overviews"; + let kind_pool = self::pool(options, app).await?; + let result = measured( + &kind_pool, + app, + admin::job_kind_overviews(&kind_pool), + |r| serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len())}), + ) + .await?; + kind_pool.close().await; + let rows = result?; + let kinds: BTreeSet<_> = rows.iter().map(|row| &row.kind).collect(); + check(kinds.len() == rows.len(), "kind overview duplicated a kind")?; + check( + rows.iter().any(|row| row.kind == "footprint_job"), + "kind overview omitted the seeded kind", + )?; + // v0.6.13 can omit raw running receipts here; record, do not require + // output equality across that known behavior change. + eprintln!( + "READ_FOOTPRINT_API {app} result={} PASS", + serde_json::to_string(&rows)? + ); + + let app = "awa_read_footprint_state_timeseries"; + let timeseries_pool = self::pool(options, app).await?; + let result = measured( + ×eries_pool, + app, + admin::state_timeseries(×eries_pool, 60), + |r| serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len())}), + ) + .await?; + timeseries_pool.close().await; + let rows = result?; + let buckets: BTreeSet<_> = rows + .iter() + .map(|row| (row.bucket, format!("{:?}", row.state))) + .collect(); + check( + buckets.len() == rows.len(), + "timeseries duplicated a bucket/state", + )?; + check(!rows.is_empty(), "timeseries omitted all fresh seeded work")?; + eprintln!( + "READ_FOOTPRINT_API {app} minutes=60 result={} PASS", + serde_json::to_string(&rows)? + ); + Ok(()) +} + +async fn failed_jobs( + store: &QueueStorage, + setup: &PgPool, + queue: &str, + count: usize, +) -> Result, Error> { + let params: Vec<_> = (0..count) + .map(|n| InsertParams { + kind: queue.to_owned(), + args: serde_json::json!({"admin_n": n, "body": "retained-terminal-body"}), + opts: InsertOpts { + queue: queue.to_owned(), + priority: 3, + max_attempts: 1, + ..Default::default() + }, + }) + .collect(); + check( + store.enqueue_params_batch(setup, ¶ms).await? == count, + "terminal seed enqueue count differs", + )?; + let mut claimed = 0; + while claimed < count { + let rows = store + .claim_runtime_batch( + setup, + queue, + (count - claimed).min(1000) as i64, + Duration::ZERO, + ) + .await?; + check(!rows.is_empty(), "terminal seed claim made no progress")?; + claimed += rows.len(); + } + let deadline = std::time::Instant::now() + Duration::from_secs(180); + let mut failed = 0; + while failed < count { + check( + std::time::Instant::now() < deadline, + "terminal seed rescue timed out", + )?; + let rows = store.rescue_stale_heartbeats(setup, Duration::ZERO).await?; + check( + rows.iter().all(|row| row.state == JobState::Failed), + "seed rescue did not exhaust its attempt", + )?; + failed += rows.len(); + if rows.is_empty() { + tokio::time::sleep(Duration::from_millis(5)).await; + } + } + let ids: Vec = sqlx::query_scalar( + "SELECT job_id FROM awa.done_entries WHERE queue=$1 AND state='failed' ORDER BY job_id", + ) + .bind(queue) + .fetch_all(setup) + .await?; + check(ids.len() == count, "terminal seed count differs")?; + Ok(ids) +} + +async fn terminal_admin_operations( + store: &QueueStorage, + setup: &PgPool, + options: &PgConnectOptions, +) -> Result<(), Error> { + for (operation, count) in [ + ("retry", 1), + ("single_dlq", 1), + ("bulk_dlq", 10), + ("discard", 10), + ] { + let queue = format!("footprint_terminal_{operation}"); + let ids = failed_jobs(store, setup, &queue, count).await?; + let app = format!("awa_read_footprint_terminal_{operation}"); + let measured = pool(options, &app).await?; + let operation_result: Result<(), Error> = async { + match operation { + "retry" => { + let row = crate::measured(&measured,&app,store.retry_job(&measured,ids[0]),|r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|usize::from(v.is_some()))})).await?? + .ok_or("terminal retry omitted job")?; + check( + row.args["body"] == "retained-terminal-body" + && row.max_attempts == 1 + && row.priority == 3, + "terminal retry lost body", + )?; + } + "single_dlq" => { + let row = crate::measured(&measured,&app,store.move_failed_to_dlq(&measured,ids[0],"footprint"),|r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|usize::from(v.is_some()))})).await?? + .ok_or("single DLQ move omitted job")?; + check( + row.args["body"] == "retained-terminal-body" && row.max_attempts == 1, + "single DLQ move lost body", + )?; + } + "bulk_dlq" => { + check( + crate::measured(&measured,&app,store.bulk_move_failed_to_dlq(&measured,None,Some(&queue),"footprint"),|r|serde_json::json!({"affected_rows":r.as_ref().ok()})).await?? + == count as u64, + "bulk DLQ move count differs", + )?; + } + "discard" => { + check( + crate::measured(&measured,&app,store.discard_failed_by_kind(&measured,&queue),|r|serde_json::json!({"affected_rows":r.as_ref().ok()})).await?? == count as u64, + "discard count differs", + )?; + } + _ => unreachable!(), + } + Ok(()) + } + .await; + measured.close().await; + operation_result?; + let terminal_left: i64 = + sqlx::query_scalar("SELECT count(*) FROM awa.done_entries WHERE queue=$1") + .bind(&queue) + .fetch_one(setup) + .await?; + check(terminal_left == 0, "terminal mutation left failed rows")?; + eprintln!("READ_FOOTPRINT_API {app} affected={count} PASS"); + if operation == "single_dlq" { + let app = "awa_read_footprint_terminal_dlq_retry"; + let measured = pool(options, app).await?; + let retry_options = awa::model::RetryFromDlqOpts::default(); + let result = crate::measured(&measured,app,store.retry_from_dlq(&measured,ids[0],&retry_options),|r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|usize::from(v.is_some()))})).await?; + measured.close().await; + let row = result?.ok_or("DLQ retry omitted job")?; + check( + row.args["body"] == "retained-terminal-body" + && row.max_attempts == 1 + && row.priority == 3, + "DLQ retry lost body", + )?; + eprintln!("READ_FOOTPRINT_API {app} affected=1 PASS"); + } + } + Ok(()) +} + +#[tokio::test] +#[ignore = "opt-in operation diagnostic; creates a disposable database"] +async fn retained_relation_locks_for_public_operations() -> Result<(), Error> { + let url = std::env::var("DATABASE_URL")?; + let admin_options = PgConnectOptions::from_str(&url)?; + let admin = pool(&admin_options, "footprint_setup").await?; + let database = format!("awa_footprint_{}", uuid::Uuid::new_v4().simple()); + sqlx::query(&format!("CREATE DATABASE {database}")) + .execute(&admin) + .await?; + let options = admin_options.database(&database); + let setup = pool(&options, "footprint_setup").await?; + let result: Result<(), Error> = async { + migrations::run(&setup).await?; + let store = QueueStorage::new(QueueStorageConfig::default())?; + // Installation prepares the actual16/8/8 substrate and activates both + // routing registries. Merely setting the active backend is insufficient. + store.install(&setup).await?; + let jobs: Vec<_> = ["footprint_plain", "footprint_deadline"] + .into_iter() + .flat_map(|queue| { + (0..20).map(move |n| InsertParams { + kind: "footprint_job".into(), + args: serde_json::json!({"n":n}), + opts: InsertOpts { + queue: queue.into(), + ..Default::default() + }, + }) + }) + .collect(); + check( + store.enqueue_params_batch(&setup, &jobs).await? == 40, + "seed count differs", + )?; + let available: i64 = sqlx::query_scalar( + "SELECT min(job_id) FROM awa.ready_entries WHERE queue='footprint_plain'", + ) + .fetch_one(&setup) + .await?; + point( + &store, + &options, + "awa_read_footprint_get_available", + available, + JobState::Available, + ) + .await?; + page( + &options, + "awa_read_footprint_list_available", + Some("footprint_plain"), + Some(JobState::Available), + Some(20), + ) + .await?; + page( + &options, + "awa_read_footprint_list_unfiltered", + Some("footprint_plain"), + None, + Some(20), + ) + .await?; + page( + &options, + "awa_read_footprint_list_global", + None, + None, + Some(20), + ) + .await?; + for (queue, suffix, deadline) in [ + ("footprint_plain", "compact", Duration::ZERO), + ("footprint_deadline", "deadline", Duration::from_secs(300)), + ] { + let claim_pool = pool(&options, &format!("awa_read_footprint_claim_{suffix}")).await?; + let app=format!("awa_read_footprint_claim_{suffix}"); + let claimed = measured(&claim_pool,&app,store.claim_runtime_batch(&claim_pool,queue,10,deadline),|r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len()),"ids":r.as_ref().ok().map(|v|v.iter().map(|j|j.job.id).collect::>())})).await?; + claim_pool.close().await; + let claimed = claimed?; + check(claimed.len() == 10, "claim count differs")?; + eprintln!("READ_FOOTPRINT_API claim_{suffix} batch=10 PASS"); + // v0.6.13 commonly lists only10available rows; the receipt-listing + // fix can list20. Both outputs must remain unique and scoped. + page( + &options, + &format!("awa_read_footprint_list_mixed_{suffix}"), + Some(queue), + None, + None, + ) + .await?; + if suffix == "compact" { + page( + &options, + "awa_read_footprint_list_global_mixed", + None, + None, + Some(20), + ) + .await?; + dashboards(&options).await?; + } + point( + &store, + &options, + &format!("awa_read_footprint_get_running_{suffix}"), + claimed[0].job.id, + JobState::Running, + ) + .await?; + let complete_pool = + pool(&options, &format!("awa_read_footprint_complete_{suffix}")).await?; + let app=format!("awa_read_footprint_complete_{suffix}"); + let completed = measured(&complete_pool,&app,store.complete_runtime_batch(&complete_pool,&claimed),|r|serde_json::json!({"returned_rows":r.as_ref().ok().map(|v|v.len())})).await?; + complete_pool.close().await; + check(completed?.len() == 10, "completion count differs")?; + eprintln!("READ_FOOTPRINT_API complete_{suffix} batch=10 PASS"); + point( + &store, + &options, + &format!("awa_read_footprint_get_completed_{suffix}"), + claimed[0].job.id, + JobState::Completed, + ) + .await?; + page( + &options, + &format!("awa_read_footprint_list_completed_{suffix}"), + Some(queue), + Some(JobState::Completed), + Some(10), + ) + .await?; + } + terminal_admin_operations(&store, &setup, &options).await?; + Ok(()) + } + .await; + setup.close().await; + let cleanup = sqlx::query(&format!("DROP DATABASE {database} WITH (FORCE)")) + .execute(&admin) + .await; + admin.close().await; + result?; + cleanup?; + Ok(()) +} + +#[tokio::test] +#[ignore = "opt-in diagnostic; creates a disposable database"] +async fn bulk_failed_to_dlq_actual_plan_at_10k() -> Result<(), Error> { + let url = std::env::var("DATABASE_URL")?; + let admin_options = PgConnectOptions::from_str(&url)?; + let admin = pool(&admin_options, "terminal_plan_setup").await?; + let database = format!("awa_terminal_plan_{}", uuid::Uuid::new_v4().simple()); + sqlx::query(&format!("CREATE DATABASE {database}")) + .execute(&admin) + .await?; + let options = admin_options.database(&database); + let setup = pool(&options, "terminal_plan_setup").await?; + let result: Result<(), Error> = async { + migrations::run(&setup).await?; + let store = QueueStorage::new(QueueStorageConfig::default())?; + store.install(&setup).await?; + let queue = "terminal_plan_10k"; + let seed_started = std::time::Instant::now(); + let ids = failed_jobs(&store, &setup, queue, 10_000).await?; + let expected: Vec<(i64, serde_json::Value)> = sqlx::query_as( + "SELECT job_id,args FROM awa.ready_entries WHERE queue=$1 ORDER BY job_id", + ).bind(queue).fetch_all(&setup).await?; + check(expected.len() == 10_000 && expected.iter().map(|row| row.0).eq(ids.iter().copied()), "10k seed identity differs")?; + sqlx::raw_sql("ANALYZE awa.done_entries; ANALYZE awa.ready_entries; ANALYZE awa.ready_tombstones") + .execute(&setup).await?; + eprintln!("TERMINAL_PLAN_SEED count=10000 seconds={:.6}", seed_started.elapsed().as_secs_f64()); + let measured = pool(&options, "awa_terminal_explain_bulk_dlq").await?; + sqlx::raw_sql("LOAD 'auto_explain'; SET auto_explain.log_min_duration=0; SET auto_explain.log_analyze=on; SET auto_explain.log_buffers=on; SET auto_explain.log_timing=off; SET auto_explain.log_format=json; SET auto_explain.log_nested_statements=on; SET auto_explain.sample_rate=1") + .execute(&measured).await?; + let settings: Vec<(String, String)> = sqlx::query_as("SELECT name,setting FROM pg_settings WHERE name LIKE 'auto_explain.%' ORDER BY name") + .fetch_all(&measured).await?; + let pid: i32 = sqlx::query_scalar("SELECT pg_backend_pid()").fetch_one(&measured).await?; + eprintln!("TERMINAL_PLAN_SETTINGS pid={pid} settings={}", serde_json::to_string(&settings)?); + eprintln!("TERMINAL_PLAN_PHASE workload_start"); + let started = std::time::Instant::now(); + let moved = store.bulk_move_failed_to_dlq(&measured, None, Some(queue), "plan-10k").await; + let seconds = started.elapsed().as_secs_f64(); + measured.close().await; + check(moved? == 10_000, "10k DLQ move count differs")?; + let actual: (i64, i64, i64) = sqlx::query_as("SELECT count(*),count(*) FILTER(WHERE args->>'body'='retained-terminal-body' AND max_attempts=1 AND priority=3),(SELECT count(*) FROM awa.done_entries WHERE queue=$1) FROM awa.dlq_entries WHERE queue=$1") + .bind(queue).fetch_one(&setup).await?; + check(actual == (10_000, 10_000, 0), "10k move lost or corrupted bodies")?; + let actual_bodies: Vec<(i64, serde_json::Value)> = sqlx::query_as( + "SELECT job_id,args FROM awa.dlq_entries WHERE queue=$1 ORDER BY job_id", + ).bind(queue).fetch_all(&setup).await?; + check(actual_bodies == expected, "10k move changed an identity or per-job body")?; + eprintln!("TERMINAL_PLAN_PHASE recovered"); + eprintln!("TERMINAL_PLAN_API moved=10000 seconds={seconds:.6} body_checks={actual:?} PASS"); + Ok(()) + }.await; + setup.close().await; + let cleanup = sqlx::query(&format!("DROP DATABASE {database} WITH (FORCE)")) + .execute(&admin) + .await; + admin.close().await; + result?; + cleanup?; + Ok(()) +} diff --git a/awa/tests/persona_soak/config.rs b/awa/tests/persona_soak/config.rs index bae8a9b03..418feebd7 100644 --- a/awa/tests/persona_soak/config.rs +++ b/awa/tests/persona_soak/config.rs @@ -169,6 +169,19 @@ fn env_parse(name: &str) -> Option { env_string(name).and_then(|value| value.trim().parse().ok()) } +pub fn pressure_rotation_interval() -> Result { + match env_string("AWA_PRESSURE_ROTATE_MULTIPLIER") + .as_deref() + .map(str::trim) + { + None | Some("1") => Ok(Duration::from_secs(1)), + Some("4") => Ok(Duration::from_secs(4)), + Some(value) => Err(format!( + "AWA_PRESSURE_ROTATE_MULTIPLIER must be 1 or 4, got {value:?}" + )), + } +} + impl SoakConfig { pub fn from_env() -> Result { let database_url = env_string("AWA_SOAK_DATABASE_URL").ok_or( @@ -185,6 +198,7 @@ impl SoakConfig { } fn from_database_url(database_url: String) -> Result { + pressure_rotation_interval()?; let database_name = database_name(&database_url); if !database_name.starts_with("awa_soak") || !database_name diff --git a/awa/tests/persona_soak/db.rs b/awa/tests/persona_soak/db.rs index a2ab41c8e..20f4d40c2 100644 --- a/awa/tests/persona_soak/db.rs +++ b/awa/tests/persona_soak/db.rs @@ -221,6 +221,7 @@ pub type ClientFactory = Arc Client + Send + Sync>; /// shutdown handshake and the connections drop. pub struct ClientHost { pub label: String, + metrics_identity: Option, /// Always `Some` until the host is stopped or dropped. runtime: Option, client: Arc, @@ -231,15 +232,24 @@ impl ClientHost { pub async fn spawn( url: String, label: String, + persona: Persona, pool_size: u32, worker_threads: usize, factory: ClientFactory, ) -> Result { let thread_label = label.clone(); tokio::task::spawn_blocking(move || { + let metrics_identity = super::gate_metrics::begin_host( + persona, + &thread_label, + &format!("soak_{thread_label}"), + )?; let runtime = tokio::runtime::Builder::new_multi_thread() .worker_threads(worker_threads) - .thread_name(format!("soak-{thread_label}")) + .thread_name(super::gate_metrics::thread_name( + metrics_identity.as_ref(), + &format!("soak-{thread_label}"), + )) .enable_all() .build() .map_err(|error| format!("build runtime: {error}"))?; @@ -247,15 +257,19 @@ impl ClientHost { let pool = connect_pool(&url, &format!("soak_{thread_label}"), pool_size) .await .map_err(|error| format!("connect pool: {error}"))?; - let client = factory(pool.clone()); + let client = super::gate_metrics::build_client(metrics_identity.as_ref(), || { + factory(pool.clone()) + }); client .start() .await .map_err(|error| format!("start client: {error}"))?; Ok::<_, String>((pool, client)) })?; + super::gate_metrics::lifecycle(metrics_identity.as_ref(), "host_started"); Ok(Self { label: thread_label, + metrics_identity, runtime: Some(runtime), client: Arc::new(client), pool, @@ -275,6 +289,7 @@ impl ClientHost { /// Graceful stop: stop claiming, drain in-flight jobs, then close the pool. pub async fn shutdown(mut self, timeout: Duration) { + super::gate_metrics::lifecycle(self.metrics_identity.as_ref(), "shutdown_requested"); let Some(runtime) = self.runtime.take() else { return; }; @@ -288,10 +303,15 @@ impl ClientHost { }) .await; runtime.shutdown_background(); + super::gate_metrics::lifecycle( + self.metrics_identity.as_ref(), + "shutdown_returned_background_requested", + ); } /// Abrupt stop: no shutdown handshake, as when a process is killed. pub fn kill(self) { + super::gate_metrics::lifecycle(self.metrics_identity.as_ref(), "kill_requested"); drop(self); } } @@ -359,6 +379,7 @@ mod tests { .expect("host runtime"); let host = ClientHost { label: "host_drop".to_string(), + metrics_identity: None, runtime: Some(runtime), client: Arc::new(client), pool, diff --git a/awa/tests/persona_soak/fleet.rs b/awa/tests/persona_soak/fleet.rs index b7e709ca1..9316cf800 100644 --- a/awa/tests/persona_soak/fleet.rs +++ b/awa/tests/persona_soak/fleet.rs @@ -99,6 +99,7 @@ impl Fleet { let host = ClientHost::spawn( self.url.clone(), format!("{}_{index}", self.name), + self.persona, self.pool_size, self.worker_threads, self.factory.clone(), diff --git a/awa/tests/persona_soak/gate_metrics.rs b/awa/tests/persona_soak/gate_metrics.rs new file mode 100644 index 000000000..6555a095d --- /dev/null +++ b/awa/tests/persona_soak/gate_metrics.rs @@ -0,0 +1,528 @@ +use super::config::Persona; +use super::shared::Shared; +use opentelemetry::metrics::{Meter, MeterProvider}; +use opentelemetry::{global, InstrumentationScope, KeyValue}; +use opentelemetry_otlp::WithExportConfig; +use opentelemetry_sdk::metrics::{PeriodicReader, SdkMeterProvider, Temporality}; +use opentelemetry_sdk::Resource; +use serde::Serialize; +use serde_json::{json, Value}; +use std::cell::RefCell; +use std::collections::HashMap; +use std::fs::{File, OpenOptions}; +use std::io::Write; +use std::marker::PhantomData; +use std::path::PathBuf; +use std::rc::Rc; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; +use std::sync::{Mutex, OnceLock}; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; + +pub const ENV_ENDPOINT: &str = "AWA_SOAK_METRICS_ENDPOINT"; +pub const ENV_DIRECTORY: &str = "AWA_SOAK_METRICS_DIR"; +pub const OUTPUT_PREFIX: &str = "AWA_SOAK_METRICS "; +pub const ERROR_MARKER: &str = "AWA_SOAK_METRICS_INCOMPLETE"; +const MAX_HOSTS: u64 = 4096; +const MAX_EVENTS: u64 = 100_000; +const MAX_LINE: usize = 4096; +const MAX_BYTES: u64 = 64 * 1024 * 1024; +static STATE: OnceLock, String>> = OnceLock::new(); +thread_local! { static ISSUER: RefCell> = const { RefCell::new(None) }; } + +struct Telemetry { + _provider: SdkMeterProvider, + role: String, + process_instance: String, + file: Mutex, + path: PathBuf, + events: AtomicU64, + bytes: AtomicU64, + next_host: AtomicU64, + failed: AtomicBool, + runtimes: Mutex>, + child: Mutex>, +} + +#[derive(Clone, Debug, Serialize, PartialEq, Eq)] +pub struct HostIdentity { + persona: String, + client: String, + instance: u64, + application: String, + thread: String, +} + +struct ScopeGuard { + previous: Option, + _not_send: PhantomData>, +} + +impl Drop for ScopeGuard { + fn drop(&mut self) { + ISSUER.with(|slot| *slot.borrow_mut() = self.previous.take()); + } +} + +fn with_identity(identity: &HostIdentity, factory: impl FnOnce() -> T) -> T { + let previous = ISSUER.with(|slot| slot.replace(Some(identity.clone()))); + let _guard = ScopeGuard { + previous, + _not_send: PhantomData, + }; + factory() +} + +fn attributed_scope(scope: InstrumentationScope, role: &str) -> InstrumentationScope { + let identity = ISSUER.with(|slot| slot.borrow().clone()); + let mut attributes: Vec<_> = scope.attributes().cloned().collect(); + let reserved = [ + "soak.persona", + "soak.client", + "soak.client.instance", + "soak.pg_application", + "soak.process.role", + ]; + if attributes + .iter() + .any(|attribute| reserved.contains(&attribute.key.as_str())) + { + if let Some(telemetry) = state() { + telemetry.failed.store(true, Ordering::Relaxed); + } + } else { + attributes.extend([ + KeyValue::new( + "soak.persona", + identity + .as_ref() + .map_or("unassigned", |identity| identity.persona.as_str()) + .to_string(), + ), + KeyValue::new( + "soak.client", + identity + .as_ref() + .map_or("unassigned", |identity| identity.client.as_str()) + .to_string(), + ), + KeyValue::new( + "soak.client.instance", + identity.as_ref().map_or(0, |identity| identity.instance) as i64, + ), + KeyValue::new( + "soak.pg_application", + identity + .as_ref() + .map_or("unassigned", |identity| identity.application.as_str()) + .to_string(), + ), + KeyValue::new("soak.process.role", role.to_string()), + ]); + } + let mut builder = + InstrumentationScope::builder(scope.name().to_string()).with_attributes(attributes); + if let Some(version) = scope.version() { + builder = builder.with_version(version.to_string()); + } + if let Some(schema) = scope.schema_url() { + builder = builder.with_schema_url(schema.to_string()); + } + builder.build() +} + +struct ScopedProvider { + provider: SdkMeterProvider, + role: String, +} +impl MeterProvider for ScopedProvider { + fn meter_with_scope(&self, scope: InstrumentationScope) -> Meter { + self.provider + .meter_with_scope(attributed_scope(scope, &self.role)) + } +} + +/// Whether OTLP capture is installed in this process. +pub fn active() -> bool { + state().is_some() +} + +fn state() -> Option<&'static Telemetry> { + STATE + .get() + .and_then(|result| result.as_ref().ok()) + .and_then(Option::as_ref) +} + +impl Telemetry { + fn record(&self, event: Value) { + let number = self.events.fetch_add(1, Ordering::Relaxed); + let line=json!({"utc":chrono::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Millis,true), + "pid":std::process::id(),"process_role":self.role,"process_instance":self.process_instance,"event":event}).to_string()+"\n"; + let bytes = self.bytes.fetch_add(line.len() as u64, Ordering::Relaxed); + if number >= MAX_EVENTS + || line.len() > MAX_LINE + || bytes.saturating_add(line.len() as u64) > MAX_BYTES + { + self.failed.store(true, Ordering::Relaxed); + if number == MAX_EVENTS || bytes < MAX_BYTES { + eprintln!("{ERROR_MARKER}"); + } + return; + } + let written = self + .file + .lock() + .map_err(|_| ()) + .and_then(|mut file| file.write_all(line.as_bytes()).map_err(|_| ())); + if written.is_err() { + self.failed.store(true, Ordering::Relaxed); + eprintln!("{ERROR_MARKER}"); + } + } +} + +pub fn install(role: &str) -> Result<(), String> { + STATE + .get_or_init(|| { + let endpoint = match std::env::var(ENV_ENDPOINT) { + Err(std::env::VarError::NotPresent) => return Ok(None), + Ok(value) if !value.is_empty() => value, + _ => return Err(format!("{ENV_ENDPOINT} must be a nonempty HTTP endpoint")), + }; + let url = reqwest::Url::parse(&endpoint) + .map_err(|_| "invalid metrics endpoint".to_string())?; + if !matches!(url.scheme(), "http" | "https") + || !url.username().is_empty() + || url.password().is_some() + || url.query().is_some() + || url.fragment().is_some() + { + return Err("metrics endpoint must be HTTP(S) without credentials, query or fragment".into()); + } + let directory = PathBuf::from( + std::env::var(ENV_DIRECTORY).map_err(|_| format!("{ENV_DIRECTORY} required"))?, + ); + if !directory.is_absolute() {return Err("metrics directory must be absolute".into());} + std::fs::create_dir_all(&directory) + .map_err(|error| format!("metrics directory: {error}"))?; + let epoch = SystemTime::now() + .duration_since(UNIX_EPOCH) + .map_err(|_| "metrics clock before epoch".to_string())? + .as_nanos(); + let process_instance = format!("{}-{epoch}", std::process::id()); + let path = directory.join(format!("{role}-{process_instance}.jsonl")); + let file = OpenOptions::new() + .write(true) + .create_new(true) + .open(&path) + .map_err(|error| format!("metrics receipt: {error}"))?; + let exporter = opentelemetry_otlp::MetricExporter::builder() + .with_tonic() + .with_endpoint(&endpoint) + .with_timeout(Duration::from_secs(3)) + .with_temporality(Temporality::Cumulative) + .build() + .map_err(|error| format!("metrics exporter: {error}"))?; + let reader = PeriodicReader::builder(exporter) + .with_interval(Duration::from_secs(5)) + .build(); + let resource = Resource::builder() + .with_service_name(format!("awa-soak-{role}")) + .with_attributes([ + KeyValue::new("service.instance.id", process_instance.clone()), + KeyValue::new("process.pid", std::process::id() as i64), + KeyValue::new("soak.process.role", role.to_string()), + ]) + .build(); + let provider = SdkMeterProvider::builder() + .with_resource(resource) + .with_reader(reader) + .build(); + global::set_meter_provider(ScopedProvider { + provider: provider.clone(), + role: role.to_string(), + }); + let telemetry = Telemetry { + _provider: provider, + role: role.to_string(), + process_instance, + file: Mutex::new(file), + path, + events: AtomicU64::new(0), + bytes: AtomicU64::new(0), + next_host: AtomicU64::new(1), + failed: AtomicBool::new(false), + runtimes: Mutex::new(HashMap::new()), + child: Mutex::new(None), + }; + telemetry.record( + json!({"kind":"initialized","endpoint":endpoint,"export_interval_ms":5000, + "delivery":"unverified","final_flush":"not_attempted","tail":"potentially_incomplete", + "caps":{"hosts":MAX_HOSTS,"events":MAX_EVENTS,"bytes":MAX_BYTES,"line_bytes":MAX_LINE}}), + ); + if telemetry.failed.load(Ordering::Relaxed) { + return Err("metrics receipt initialization failed".into()); + } + if role == "claim_child" { + println!("{OUTPUT_PREFIX}{}", json!({"kind":"initialized","pid":std::process::id(), + "process_role":role,"process_instance":telemetry.process_instance,"receipt":telemetry.path, + "export_interval_ms":5000,"delivery":"unverified","final_flush":"not_attempted","tail":"potentially_incomplete"})); + } + Ok(Some(telemetry)) + }) + .as_ref() + .map(|_| ()) + .map_err(Clone::clone) +} + +pub fn begin_host( + persona: Persona, + client: &str, + application: &str, +) -> Result, String> { + let Some(telemetry) = state() else { + return Ok(None); + }; + let instance = telemetry.next_host.fetch_add(1, Ordering::Relaxed); + if instance > MAX_HOSTS { + telemetry.failed.store(true, Ordering::Relaxed); + return Err("metrics host identity cap exceeded".into()); + } + let identity = HostIdentity { + persona: persona.name().to_string(), + client: client.to_string(), + instance, + application: application.to_string(), + thread: format!("soak-{client}-{instance}"), + }; + telemetry + .runtimes + .lock() + .map_err(|_| "metrics runtime map poisoned".to_string())? + .insert(identity.thread.clone(), identity.clone()); + if telemetry.role == "claim_child" { + *telemetry + .child + .lock() + .map_err(|_| "metrics child map poisoned".to_string())? = Some(identity.clone()); + } + telemetry.record(json!({"kind":"host_construct","issuer":identity})); + if telemetry.failed.load(Ordering::Relaxed) { + return Err("metrics host receipt failed".into()); + } + Ok(Some(identity)) +} + +pub fn thread_name(identity: Option<&HostIdentity>, fallback: &str) -> String { + identity.map_or_else(|| fallback.to_string(), |identity| identity.thread.clone()) +} + +pub fn build_client( + identity: Option<&HostIdentity>, + factory: impl FnOnce() -> awa::Client, +) -> awa::Client { + match identity { + Some(identity) => with_identity(identity, factory), + None => factory(), + } +} + +pub fn lifecycle(identity: Option<&HostIdentity>, kind: &str) { + if let (Some(telemetry), Some(identity)) = (state(), identity) { + telemetry.record(json!({"kind":kind,"issuer":identity,"final_flush":"not_attempted","tail":"potentially_incomplete"})); + } +} + +pub fn prune_ring(message: &str) -> Option<&'static str> { + match message.trim_matches('"') { + "Failed to prune queue storage queue segments" => Some("queue"), + "Failed to prune queue storage lease segments" => Some("lease"), + "Failed to prune queue storage claim segments" => Some("claim"), + _ => None, + } +} + +pub fn prune_error(ring: &str) { + let Some(telemetry) = state() else { + return; + }; + let current = std::thread::current(); + let thread = current.name().unwrap_or("unassigned"); + let identity = telemetry + .runtimes + .lock() + .ok() + .and_then(|runtimes| runtimes.get(thread).cloned()) + .or_else(|| { + telemetry + .child + .lock() + .ok() + .and_then(|identity| identity.clone()) + }); + telemetry.record(json!({"kind":"prune_error_event","ring":ring,"issuer":identity,"thread":thread, + "attribution":if identity.is_some(){"known_runtime"}else{"unassigned"},"source":"rust_trace_supplement"})); +} + +pub fn absorb_output(shared: &Shared, line: &str) -> bool { + if line == ERROR_MARKER { + shared.incomplete("child metrics instrumentation failed", vec![]); + return true; + } + let Some(payload) = line.strip_prefix(OUTPUT_PREFIX) else { + return false; + }; + if payload.len() > MAX_LINE || serde_json::from_str::(payload).is_err() { + shared.incomplete("invalid child metrics receipt", vec![]); + } else { + shared.note("gate_metrics_child", payload); + } + true +} + +pub fn reconcile(shared: &Shared) { + if let Some(telemetry) = state() { + telemetry.record(json!({"kind":"measurement_end","final_flush":"not_attempted","tail":"potentially_incomplete", + "python_baseline_prune_errors":"unavailable"})); + shared.note("gate_metrics",format!("receipt={}; fixed 5s OTLP collection; delivery and missing tails require external raw-file validation; no flush wait added",telemetry.path.display())); + if telemetry.failed.load(Ordering::Relaxed) { + shared.incomplete( + "metrics receipt cap, scope collision, or write failure", + vec![], + ); + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + fn identity(name: &str, instance: u64) -> HostIdentity { + HostIdentity { + persona: name.into(), + client: name.into(), + instance, + application: format!("soak_{name}"), + thread: name.into(), + } + } + fn scope() -> InstrumentationScope { + InstrumentationScope::builder("awa") + .with_version("1") + .with_schema_url("https://example.invalid/schema") + .with_attributes([KeyValue::new("original", "kept")]) + .build() + } + fn attribute(scope: &InstrumentationScope, key: &str) -> String { + scope + .attributes() + .find(|attribute| attribute.key.as_str() == key) + .expect("attribute") + .value + .to_string() + } + #[test] + fn scopes_preserve_original_metadata_and_unknown_issuers() { + let attributed = attributed_scope(scope(), "parent"); + assert_eq!(attributed.name(), "awa"); + assert_eq!(attributed.version(), Some("1")); + assert_eq!( + attributed.schema_url(), + Some("https://example.invalid/schema") + ); + assert_eq!(attribute(&attributed, "original"), "kept"); + assert_eq!(attribute(&attributed, "soak.persona"), "unassigned"); + } + #[test] + fn nested_scope_and_panic_restore_previous_identity() { + let outer = identity("outer", 1); + let inner = identity("inner", 2); + with_identity(&outer, || { + let captured = with_identity(&inner, || attributed_scope(scope(), "parent")); + assert_eq!(attribute(&captured, "soak.persona"), "inner"); + let _ = std::panic::catch_unwind(|| with_identity(&inner, || panic!("scope control"))); + assert_eq!( + attribute(&attributed_scope(scope(), "parent"), "soak.persona"), + "outer" + ); + assert_eq!(attribute(&captured, "soak.persona"), "inner"); + }); + assert_eq!( + attribute(&attributed_scope(scope(), "parent"), "soak.persona"), + "unassigned" + ); + } + #[test] + fn concurrent_construction_scopes_survive_later_records_outside_the_factory() { + let exporter = opentelemetry_sdk::metrics::InMemoryMetricExporter::default(); + let sdk = SdkMeterProvider::builder() + .with_reader( + PeriodicReader::builder(exporter.clone()) + .with_interval(Duration::from_secs(60)) + .build(), + ) + .build(); + let provider = std::sync::Arc::new(ScopedProvider { + provider: sdk.clone(), + role: "parent".into(), + }); + let barrier = std::sync::Arc::new(std::sync::Barrier::new(2)); + let handles: Vec<_> = [("mia", 1), ("priya", 2)] + .into_iter() + .map(|(name, instance)| { + let barrier = barrier.clone(); + let provider = provider.clone(); + std::thread::spawn(move || { + with_identity(&identity(name, instance), || { + barrier.wait(); + provider + .meter_with_scope(scope()) + .u64_counter("scope.control") + .build() + }) + }) + }) + .collect(); + let counters: Vec<_> = handles + .into_iter() + .map(|handle| handle.join().expect("thread")) + .collect(); + for counter in counters { + counter.add(1, &[]); + } + sdk.force_flush().expect("in-memory flush"); + let metrics = exporter.get_finished_metrics().expect("captured metrics"); + let mut personas: Vec<_> = metrics + .iter() + .flat_map(|resource| resource.scope_metrics()) + .map(|metrics| attribute(metrics.scope(), "soak.persona")) + .collect(); + personas.sort(); + assert_eq!(personas, vec!["mia", "priya"]); + for metrics in metrics.iter().flat_map(|resource| resource.scope_metrics()) { + assert_eq!(metrics.scope().name(), "awa"); + assert_eq!(metrics.scope().version(), Some("1")); + assert_eq!(attribute(metrics.scope(), "original"), "kept"); + } + sdk.shutdown().expect("in-memory shutdown"); + } + #[test] + fn only_stable_prune_error_messages_match() { + assert_eq!( + prune_ring("Failed to prune queue storage queue segments"), + Some("queue") + ); + assert_eq!( + prune_ring("Failed to prune queue storage lease segments"), + Some("lease") + ); + assert_eq!( + prune_ring("Failed to prune queue storage claim segments"), + Some("claim") + ); + assert_eq!( + prune_ring("wrapped: Failed to prune queue storage claim segments"), + None + ); + } +} diff --git a/awa/tests/persona_soak/gate_proof.rs b/awa/tests/persona_soak/gate_proof.rs new file mode 100644 index 000000000..23f2d6fa5 --- /dev/null +++ b/awa/tests/persona_soak/gate_proof.rs @@ -0,0 +1,756 @@ +use super::config::Persona; +use super::ledger::{expect, flag, samples_terminal_proof, JobRecord}; +use super::shared::Shared; +use awa::JobRow; +use sqlx::PgPool; +use std::collections::{HashMap, HashSet}; +use std::future::Future; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; +use tokio::runtime::Handle; + +pub const ENV_ENABLED: &str = "AWA_SOAK_GATE_PROOF"; +pub const ENV_URL: &str = "AWA_SOAK_GATE_PROOF_URL"; +pub const ERROR_MARKER: &str = "AWA_SOAK_GATE_PROOF_INCOMPLETE"; +const TIMEOUT: Duration = Duration::from_secs(2); +const WITNESS_WRITE_TIMEOUT: Duration = Duration::from_secs(5); +const MAX_PENDING: usize = 100_000; +const MAX_ROWS: i64 = 100_001; + +type WitnessStats = Arc>>; + +pub struct GateProof { + owner: Handle, + pool: PgPool, + write_pool: Option, + write_stats: WitnessStats, + reported_lease_duplicates: Mutex>, +} + +pub fn enabled_from_env() -> Result { + match std::env::var(ENV_ENABLED).as_deref() { + Ok("1") => Ok(true), + Ok("0") | Err(std::env::VarError::NotPresent) => Ok(false), + _ => Err(format!("{ENV_ENABLED} must be 0 or 1")), + } +} + +struct WitnessCaller { + abort: tokio::task::AbortHandle, + stats: WitnessStats, + pending: bool, +} + +impl Drop for WitnessCaller { + fn drop(&mut self) { + self.abort.abort(); + if self.pending { + *self + .stats + .lock() + .expect("proof write stats") + .entry("caller_cancellations") + .or_default() += 1; + } + } +} + +async fn write_on_owner( + owner: &Handle, + deadline: tokio::time::Instant, + stats: WitnessStats, + write: impl Future> + Send + 'static, +) -> Result<(), String> { + let task = owner.spawn(async move { + if tokio::time::Instant::now() >= deadline { + return Err("owner dispatch timeout".to_string()); + } + write.await + }); + let mut caller = WitnessCaller { + abort: task.abort_handle(), + stats: stats.clone(), + pending: true, + }; + let result = tokio::time::timeout_at(deadline, task).await; + caller.pending = false; + match result { + Ok(Ok(result)) => result, + Ok(Err(error)) => { + *stats + .lock() + .expect("proof write stats") + .entry("owner_join_errors") + .or_default() += 1; + Err(format!("owner task failed: {error}")) + } + Err(_) => { + *stats + .lock() + .expect("proof write stats") + .entry("owner_timeouts") + .or_default() += 1; + Err("owner dispatch/ack timeout".to_string()) + } + } +} + +impl GateProof { + async fn connect( + url: &str, + max_connections: u32, + application: &str, + statement_timeout: Duration, + ) -> Result { + let pool = tokio::time::timeout( + TIMEOUT, + super::db::connect_pool_with_timeout( + url, + application, + max_connections, + Some(statement_timeout), + ), + ) + .await + .map_err(|_| "proof pool connect timeout".to_string())? + .map_err(|error| format!("proof pool connect: {error}"))?; + Ok(Self { + owner: Handle::current(), + pool, + write_pool: None, + write_stats: Arc::new(Mutex::new(HashMap::new())), + reported_lease_duplicates: Mutex::new(HashSet::new()), + }) + } + + pub fn owned_url(shared: &Shared) -> String { + if shared.config.has(Persona::ShardOps) { + super::roles::url_for_role(&shared.config, super::roles::OWNER) + } else { + shared.config.database_url.clone() + } + } + + pub async fn install(shared: &Arc) -> Result<(), String> { + // The persona fleets share what is left, so the proof's pools come out of the + // same budget instead of the headroom kept for the oracle and chaos sessions. + let audit_connections = shared.budget.reserve("gate-proof-audit", 2, 1); + let witness_connections = shared.budget.reserve("gate-proof-witness", 16, 1); + // One witness connection each in the python and claim-and-abandon processes. + shared.budget.reserve("gate-proof-children", 2, 0); + let mut proof = Self::connect( + &Self::owned_url(shared), + audit_connections, + "awa_gate_proof_parent_audit", + TIMEOUT, + ) + .await?; + proof.write_pool = Some( + Self::connect( + &Self::owned_url(shared), + witness_connections, + "awa_gate_proof_parent_witness", + WITNESS_WRITE_TIMEOUT, + ) + .await? + .pool, + ); + let setup_pool = &proof.pool; + let schema = shared.info.queue_storage_schema.as_deref().unwrap_or("awa"); + if !schema.starts_with(|c: char| c.is_ascii_lowercase() || c == '_') + || !schema + .chars() + .all(|c| c.is_ascii_lowercase() || c.is_ascii_digit() || c == '_') + { + return Err("invalid proof queue schema".into()); + } + let setup = include_str!("gate_proof.sql").replace("__SCHEMA__", schema); + tokio::time::timeout( + Duration::from_secs(10), + sqlx::raw_sql(&setup).execute(setup_pool), + ) + .await + .map_err(|_| "proof setup deadline exceeded".to_string())? + .map_err(|error| format!("proof setup: {error}"))?; + for (parent, trigger) in [ + ( + format!("{schema}.done_entries"), + "awa_soak_audit_done_insert", + ), + ( + format!("{schema}.receipt_completion_batches"), + "awa_soak_audit_receipt_insert", + ), + ] { + let coverage: (i64, i64) = tokio::time::timeout( + TIMEOUT, + sqlx::query_as( + "SELECT count(*),count(*) FILTER(WHERE EXISTS( + SELECT 1 FROM pg_trigger AS installed + WHERE installed.tgrelid=tree.relid AND installed.tgname=$2 + AND installed.tgtype=5 AND installed.tgenabled='O')) + FROM pg_partition_tree($1::text::regclass) AS tree", + ) + .bind(parent) + .bind(trigger) + .fetch_one(setup_pool), + ) + .await + .map_err(|_| "proof trigger coverage timeout".to_string())? + .map_err(|error| format!("proof trigger coverage: {error}"))?; + if coverage.0 < 2 || coverage.0 != coverage.1 { + return Err(format!("proof trigger coverage incomplete: {coverage:?}")); + } + } + let persistent: i64=tokio::time::timeout(TIMEOUT,sqlx::query_scalar( + "SELECT count(*) FROM pg_class + WHERE oid IN ('public.awa_soak_handler_returns'::regclass,'public.awa_soak_completed_inserts'::regclass) + AND relpersistence='p'" + ).fetch_one(setup_pool)).await.map_err(|_|"proof persistence timeout".to_string())? + .map_err(|error|format!("proof persistence: {error}"))?; + if persistent != 2 { + return Err("proof tables are not both logged".into()); + } + let quiet: i64 = tokio::time::timeout( + TIMEOUT, + sqlx::query_scalar( + "SELECT count(*) FROM pg_class AS proof + JOIN pg_class AS toast ON toast.oid=proof.reltoastrelid + WHERE proof.oid IN ('public.awa_soak_handler_returns'::regclass, + 'public.awa_soak_completed_inserts'::regclass) + AND toast.relpersistence='p' + AND EXISTS (SELECT 1 FROM pg_options_to_table(proof.reloptions) + WHERE option_name='autovacuum_enabled' AND option_value='false') + AND EXISTS (SELECT 1 FROM pg_options_to_table(toast.reloptions) + WHERE option_name='autovacuum_enabled' AND option_value='false')", + ) + .fetch_one(setup_pool), + ) + .await + .map_err(|_| "proof autovacuum validation timeout".to_string())? + .map_err(|error| format!("proof autovacuum validation: {error}"))?; + if quiet != 2 { + return Err("proof heaps and TOAST tables must explicitly disable autovacuum".into()); + } + let trusted: i64 = tokio::time::timeout( + TIMEOUT, + sqlx::query_scalar( + "SELECT count(*) FROM pg_proc + WHERE oid IN ('public.awa_soak_audit_done_insert()'::regprocedure, + 'public.awa_soak_audit_receipt_insert()'::regprocedure) + AND prosecdef AND proowner=current_user::regrole + AND proconfig=ARRAY['search_path=pg_catalog']", + ) + .fetch_one(setup_pool), + ) + .await + .map_err(|_| "proof function validation timeout".to_string())? + .map_err(|error| format!("proof function validation: {error}"))?; + if trusted != 2 { + return Err("proof functions lack the fixture owner/fixed search_path".into()); + } + + shared + .gate_proof + .set(proof) + .map_err(|_| "proof installed twice".to_string())?; + shared.run.add("gate_proof_enabled", 1); + shared.run.add("gate_proof_parent_max_connections", 18); + shared + .run + .add("gate_proof_parent_witness_max_connections", 16); + shared.run.add("gate_proof_parent_audit_max_connections", 2); + shared.note("gate_proof","logged handler-return and completion-insert audit enabled; extra SQL/WAL and up to 18 parent (16 witness + 2 audit) + 1 Rust-child + 1 Python-child connections; product pools,subscriptions,aging and retention unchanged"); + Ok(()) + } + + pub async fn child() -> Result, String> { + if !enabled_from_env()? { + return Ok(None); + } + let url = std::env::var(ENV_URL) + .map_err(|_| "owned proof URL not passed to child".to_string())?; + Self::connect(&url, 1, "awa_gate_proof_child", WITNESS_WRITE_TIMEOUT) + .await + .map(Some) + } + + pub async fn returned_completed(&self, job: &JobRow, persona: &str) -> Result<(), String> { + let pool = self.write_pool.as_ref().unwrap_or(&self.pool).clone(); + let started = Instant::now(); + let deadline_at = tokio::time::Instant::now() + WITNESS_WRITE_TIMEOUT; + let pool_size = pool.size(); + let pool_idle = pool.num_idle(); + let job_id = job.id; + let run_lease = job.run_lease; + let queue = job.queue.clone(); + let request_persona = persona.to_string(); + let write_stats = self.write_stats.clone(); + write_on_owner(&self.owner, deadline_at, self.write_stats.clone(), async move { + let acquired = tokio::time::timeout_at(deadline_at, pool.acquire()).await; + let acquire_us = started.elapsed().as_micros().min(i64::MAX as u128) as i64; + let execute_started = Instant::now(); + let (failure_kind, result) = match acquired { + Err(_) => (Some("acquire_timeouts"), Err("acquire timeout".to_string())), + Ok(Err(error)) => (Some("acquire_errors"), Err(format!("acquire error: {error}"))), + Ok(Ok(mut connection)) => { + match tokio::time::timeout_at(deadline_at, sqlx::query( + "INSERT INTO public.awa_soak_handler_returns(job_id,run_lease,queue,persona,outcome) + VALUES($1,$2,$3,$4,'completed')" + ).bind(job_id).bind(run_lease).bind(&queue).bind(&request_persona).execute(&mut *connection)).await { + Err(_) => (Some("execute_timeouts"), Err("execute timeout".to_string())), + Ok(Err(error)) => (Some("execute_errors"), Err(format!("execute error: {error}"))), + Ok(Ok(_)) => (None, Ok(())), + } + } + }; + let execute_us = if matches!(failure_kind, Some("acquire_timeouts" | "acquire_errors")) { + 0 + } else { + execute_started.elapsed().as_micros().min(i64::MAX as u128) as i64 + }; + { + let mut stats = write_stats.lock().expect("proof write stats"); + for (name, value) in [ + ("attempts", 1), + ("acquire_us", acquire_us), + ("execute_us", execute_us), + ("pool_size_sum", i64::from(pool_size)), + ("pool_idle_sum", pool_idle as i64), + ] { + *stats.entry(name).or_default() += value; + } + if let Some(kind) = failure_kind { + *stats.entry(kind).or_default() += 1; + } + } + result.map_err(|error| format!("{error}; acquire_us={acquire_us} execute_us={execute_us} pool_size={pool_size} pool_idle={pool_idle}")) + }).await.map_err(|error| format!("handler return proof {error}; job_id={} run_lease={} persona={persona}",job.id,job.run_lease)) + } + + fn publish_write_stats(&self, shared: &Shared) { + let stats = std::mem::take(&mut *self.write_stats.lock().expect("proof write stats")); + for (name, value) in stats { + shared.run.add(&format!("gate_proof_witness_{name}"), value); + } + } + + pub async fn close(&self) -> Result<(), String> { + tokio::time::timeout(TIMEOUT, async { + tokio::join!(self.pool.close(), async { + if let Some(pool) = &self.write_pool { + pool.close().await; + } + }); + }) + .await + .map_err(|_| "proof pools close timeout".to_string()) + } +} + +pub fn absorb_error(shared: &Shared, line: &str) -> bool { + if line != ERROR_MARKER { + return false; + } + shared.incomplete( + "child handler-return proof failed; execution witness incomplete", + vec![], + ); + true +} + +pub async fn observe(shared: &Shared) { + let Some(proof) = shared.gate_proof.get() else { + return; + }; + proof.publish_write_stats(shared); + let pool = &proof.pool; + let mut pending = Vec::new(); + shared.ledger.for_each(|id, record| { + if ((record.has(flag::RETURNED_COMPLETED) && !record.has(flag::NO_EVENTS)) + || samples_terminal_proof(id)) + && !record.has_durable_terminal() + && !record.has(flag::OPERATOR_REMOVED) + && !record.has(flag::DLQ_PURGED) + && pending.len() <= MAX_PENDING + { + pending.push((id, record.latest_run_lease, record.has(flag::NO_EVENTS))); + } + }); + if pending.len() > MAX_PENDING { + shared.incomplete("proof observer pending cap exceeded", vec![]); + return; + } + if pending.is_empty() { + return; + } + let ids: Vec<_> = pending.iter().map(|row| row.0).collect(); + let leases: Vec<_> = pending.iter().map(|row| row.1).collect(); + let no_events: Vec<_> = pending.iter().map(|row| row.2).collect(); + let schema = shared.info.queue_storage_schema.as_deref().unwrap_or("awa"); + let started = Instant::now(); + shared.run.add("gate_proof_observer_queries", 1); + let rows=tokio::time::timeout(TIMEOUT,sqlx::query_as::<_,(i64,i64,String)>(&format!( + "WITH pending AS (SELECT * FROM unnest($1::bigint[],$2::bigint[],$3::boolean[]) AS refs(job_id,run_lease,no_events)) + SELECT DISTINCT audit.job_id,audit.run_lease,'completed'::text + FROM public.awa_soak_completed_inserts AS audit JOIN pending ON audit.job_id=pending.job_id + AND ((pending.no_events AND audit.run_lease>=pending.run_lease) + OR (NOT pending.no_events AND audit.run_lease=pending.run_lease)) + UNION ALL SELECT done.job_id,done.run_lease,done.state::text FROM {schema}.done_entries AS done + JOIN pending ON done.job_id=pending.job_id + AND ((pending.no_events AND done.run_lease>=pending.run_lease) + OR (NOT pending.no_events AND done.run_lease=pending.run_lease)) WHERE done.state<>'completed' + UNION ALL SELECT dlq.job_id,dlq.run_lease,'failed' FROM {schema}.dlq_entries AS dlq + JOIN pending ON dlq.job_id=pending.job_id + AND ((pending.no_events AND dlq.run_lease>=pending.run_lease) + OR (NOT pending.no_events AND dlq.run_lease=pending.run_lease)) LIMIT $4" + )).bind(&ids).bind(&leases).bind(&no_events).bind(MAX_ROWS).fetch_all(pool)).await; + shared.run.add( + "gate_proof_observer_us", + started.elapsed().as_micros().min(i64::MAX as u128) as i64, + ); + match rows { + Ok(Ok(rows)) if rows.len() <= MAX_PENDING => { + shared + .run + .add("gate_proof_observed_rows", rows.len() as i64); + let now = shared.now_ms() as u32; + for (id, lease, state) in rows { + shared.ledger.with( + id, + || JobRecord::new(Persona::Chaos, u32::MAX, now, expect::ANY_TERMINAL, 0), + |record| record.note_observed_terminal(lease, &state), + ); + } + } + failure => shared.incomplete(format!("proof observer incomplete: {failure:?}"), vec![]), + } +} + +pub async fn check_lease_duplicates(shared: &Shared) { + let Some(proof) = shared.gate_proof.get() else { + return; + }; + let pool = &proof.pool; + let schema = shared.info.queue_storage_schema.as_deref().unwrap_or("awa"); + let started = Instant::now(); + shared.run.add("gate_proof_lease_snapshot_queries", 1); + let result = tokio::time::timeout( + TIMEOUT, + sqlx::query_as::<_, (i64, i64, i64)>(&format!( + "SELECT job_id,run_lease,count(*) FROM {schema}.leases + GROUP BY job_id,run_lease HAVING count(*)>1 ORDER BY job_id,run_lease LIMIT 25" + )) + .fetch_all(pool), + ) + .await; + shared.run.add( + "gate_proof_lease_snapshot_us", + started.elapsed().as_micros().min(i64::MAX as u128) as i64, + ); + match result { + Ok(Ok(rows)) => { + let mut reported = proof + .reported_lease_duplicates + .lock() + .expect("lease duplicate proof"); + let rows: Vec<_> = rows + .into_iter() + .filter(|row| reported.insert((row.0, row.1))) + .map(|(id, lease, count)| { + serde_json::json!({"job_id":id,"run_lease":lease,"count":count}).to_string() + }) + .collect(); + if !rows.is_empty() { + shared.violation( + "duplicate_materialized_leases", + "snapshot found duplicate materialized lease identities; receipts are excluded", + rows, + ); + } + } + failure => shared.incomplete( + format!("materialized lease duplicate snapshot incomplete: {failure:?}"), + vec![], + ), + } +} + +pub async fn reconcile(shared: &Shared) { + let Some(proof) = shared.gate_proof.get() else { + return; + }; + proof.publish_write_stats(shared); + let started = Instant::now(); + let deadline = tokio::time::Instant::now() + Duration::from_secs(5); + let counts = tokio::time::timeout_at( + deadline, + sqlx::query_as::<_, (i64, i64, i64, i64)>( + "SELECT handler.rows,handler.pairs,completed.rows,completed.pairs + FROM (SELECT coalesce(sum(n),0)::bigint AS rows,count(*) AS pairs + FROM (SELECT count(*) AS n FROM public.awa_soak_handler_returns + GROUP BY job_id,run_lease) AS pairs) AS handler + CROSS JOIN (SELECT coalesce(sum(n),0)::bigint AS rows,count(*) AS pairs + FROM (SELECT count(*) AS n FROM public.awa_soak_completed_inserts + GROUP BY job_id,run_lease) AS pairs) AS completed", + ) + .fetch_one(&proof.pool), + ) + .await; + match counts { + Ok(Ok((returns, return_pairs, inserts, completed_pairs))) => { + for (name, value) in [ + ("gate_handler_return_rows", returns), + ("gate_handler_return_unique_pairs", return_pairs), + ("gate_completed_insert_rows", inserts), + ("gate_completed_unique_pairs", completed_pairs), + ] { + shared.run.add(name, value); + } + shared.note("gate_proof",format!("final counts in {:?}; handler rows={returns},handler pairs={return_pairs},committed completed insert rows={inserts},unique completed pairs={completed_pairs}; handler returns are not commits; stale returned pairs need not complete",started.elapsed())); + if inserts > completed_pairs { + let details = tokio::time::timeout_at( + deadline, + sqlx::query_as::<_, (i64, i64, i64)>( + "SELECT job_id,run_lease,count(*) FROM public.awa_soak_completed_inserts + GROUP BY job_id,run_lease HAVING count(*)>1 ORDER BY job_id,run_lease LIMIT 25", + ) + .fetch_all(&proof.pool), + ) + .await; + let rows = match details { + Ok(Ok(duplicates)) => duplicates + .into_iter() + .map(|(id, lease, count)| { + serde_json::json!({"job_id":id,"run_lease":lease,"count":count}) + .to_string() + }) + .collect(), + failure => { + let message = format!( + "full completion proof duplicate details incomplete: {failure:?}" + ); + shared.note("gate_proof", message.clone()); + shared.incomplete(message, vec![]); + vec![] + } + }; + shared.violation("duplicate_completed_inserts",format!("{inserts} completed insert facts for {completed_pairs} distinct attempt pairs"),rows); + } + } + failure => { + let message = format!("full completion proof counts incomplete: {failure:?}"); + shared.note("gate_proof", message.clone()); + shared.incomplete(message, vec![]); + } + } + shared.run.add( + "gate_proof_reconcile_us", + started.elapsed().as_micros().min(i64::MAX as u128) as i64, + ); + check_lease_duplicates(shared).await; +} + +#[cfg(test)] +mod witness_owner_tests { + use super::*; + use std::sync::atomic::{AtomicBool, Ordering}; + use tokio::io::{AsyncReadExt, AsyncWriteExt}; + + fn stats() -> WitnessStats { + Arc::new(Mutex::new(HashMap::new())) + } + + fn runtime() -> tokio::runtime::Runtime { + tokio::runtime::Builder::new_multi_thread() + .worker_threads(1) + .enable_all() + .build() + .expect("test runtime") + } + + #[test] + fn witness_io_survives_caller_runtime_shutdown() { + let owner = runtime(); + let address = owner.block_on(async { + let listener = tokio::net::TcpListener::bind("127.0.0.1:0") + .await + .expect("bind echo server"); + let address = listener.local_addr().expect("echo address"); + tokio::spawn(async move { + let (mut socket, _) = listener.accept().await.expect("accept socket"); + while let Ok(value) = socket.read_u8().await { + socket.write_u8(value).await.expect("echo byte"); + } + }); + address + }); + let socket = Arc::new(tokio::sync::Mutex::new(None::)); + let first_socket = socket.clone(); + let first_caller = runtime(); + first_caller + .block_on(write_on_owner( + owner.handle(), + tokio::time::Instant::now() + Duration::from_secs(2), + stats(), + async move { + let mut connection = tokio::net::TcpStream::connect(address) + .await + .map_err(|error| error.to_string())?; + connection + .write_u8(41) + .await + .map_err(|error| error.to_string())?; + assert_eq!( + connection + .read_u8() + .await + .map_err(|error| error.to_string())?, + 41 + ); + *first_socket.lock().await = Some(connection); + Ok(()) + }, + )) + .expect("first owned socket write"); + first_caller.shutdown_timeout(Duration::from_secs(1)); + let next_caller = runtime(); + next_caller + .block_on(write_on_owner( + owner.handle(), + tokio::time::Instant::now() + Duration::from_secs(2), + stats(), + async move { + let mut socket = socket.lock().await; + let connection = socket.as_mut().expect("reused socket"); + connection + .write_u8(42) + .await + .map_err(|error| error.to_string())?; + assert_eq!( + connection + .read_u8() + .await + .map_err(|error| error.to_string())?, + 42 + ); + Ok(()) + }, + )) + .expect("socket survives original caller runtime"); + } + + struct Dropped(std::sync::mpsc::Sender<()>); + + impl Drop for Dropped { + fn drop(&mut self) { + let _ = self.0.send(()); + } + } + + #[test] + fn canceling_witness_wait_aborts_owned_task() { + let owner = runtime(); + let caller = runtime(); + let owner_handle = owner.handle().clone(); + let stats = stats(); + let caller_stats = stats.clone(); + let (started, started_rx) = tokio::sync::oneshot::channel(); + let (dropped, dropped_rx) = std::sync::mpsc::channel(); + caller.block_on(async move { + let waiter = tokio::spawn(async move { + write_on_owner( + &owner_handle, + tokio::time::Instant::now() + Duration::from_secs(2), + caller_stats, + async move { + let _guard = Dropped(dropped); + started.send(()).expect("signal started"); + std::future::pending::<()>().await; + Ok(()) + }, + ) + .await + }); + started_rx.await.expect("owned task started"); + waiter.abort(); + assert!(waiter.await.expect_err("caller canceled").is_cancelled()); + }); + dropped_rx + .recv_timeout(Duration::from_secs(2)) + .expect("owned task canceled instead of detached"); + assert_eq!( + stats.lock().expect("stats").get("caller_cancellations"), + Some(&1) + ); + } + + #[test] + fn witness_deadline_includes_owner_dispatch() { + let owner = tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("undriven owner runtime"); + let caller = runtime(); + let polled = Arc::new(AtomicBool::new(false)); + let operation_polled = polled.clone(); + let stats = stats(); + let started = Instant::now(); + let result = caller.block_on(write_on_owner( + owner.handle(), + tokio::time::Instant::now() + Duration::from_millis(100), + stats.clone(), + async move { + operation_polled.store(true, Ordering::Relaxed); + Ok(()) + }, + )); + assert!(result.expect_err("dispatch bounded").contains("timeout")); + assert!(!polled.load(Ordering::Relaxed)); + assert!(started.elapsed() < Duration::from_secs(1)); + assert_eq!(stats.lock().expect("stats").get("owner_timeouts"), Some(&1)); + } + + #[test] + fn witness_write_has_one_absolute_deadline() { + let owner = runtime(); + let caller = runtime(); + let finished = Arc::new(AtomicBool::new(false)); + let operation_finished = finished.clone(); + let started = Instant::now(); + let result = caller.block_on(write_on_owner( + owner.handle(), + tokio::time::Instant::now() + Duration::from_millis(200), + stats(), + async move { + tokio::time::sleep(Duration::from_millis(120)).await; + tokio::time::sleep(Duration::from_millis(120)).await; + operation_finished.store(true, Ordering::Relaxed); + Ok(()) + }, + )); + assert!(result.expect_err("one total budget").contains("timeout")); + assert!(!finished.load(Ordering::Relaxed)); + assert!(started.elapsed() < Duration::from_secs(1)); + } + + #[test] + fn witness_owner_panic_is_an_error() { + let owner = runtime(); + let caller = runtime(); + let stats = stats(); + let result = caller.block_on(write_on_owner( + owner.handle(), + tokio::time::Instant::now() + Duration::from_secs(2), + stats.clone(), + async { panic!("owned write control") }, + )); + assert!(result + .expect_err("join panic surfaced") + .contains("owner task failed")); + assert_eq!( + stats.lock().expect("stats").get("owner_join_errors"), + Some(&1) + ); + } +} diff --git a/awa/tests/persona_soak/gate_proof.sql b/awa/tests/persona_soak/gate_proof.sql new file mode 100644 index 000000000..9667432b3 --- /dev/null +++ b/awa/tests/persona_soak/gate_proof.sql @@ -0,0 +1,46 @@ +BEGIN; +CREATE TABLE public.awa_soak_handler_returns ( + event_id bigserial PRIMARY KEY, + job_id bigint NOT NULL, + run_lease bigint NOT NULL, + queue text NOT NULL, + persona text NOT NULL, + outcome text NOT NULL, + returned_at timestamptz NOT NULL DEFAULT clock_timestamp() +) USING heap WITH (autovacuum_enabled=false, toast.autovacuum_enabled=false); +CREATE INDEX awa_soak_handler_returns_pair ON public.awa_soak_handler_returns(job_id,run_lease); +CREATE TABLE public.awa_soak_completed_inserts ( + event_id bigserial PRIMARY KEY, + job_id bigint NOT NULL, + run_lease bigint NOT NULL, + attempt smallint NOT NULL, + queue text NOT NULL, + writer_shape text NOT NULL, + recorded_at timestamptz NOT NULL DEFAULT clock_timestamp() +) USING heap WITH (autovacuum_enabled=false, toast.autovacuum_enabled=false); +CREATE INDEX awa_soak_completed_inserts_pair ON public.awa_soak_completed_inserts(job_id,run_lease); +CREATE FUNCTION public.awa_soak_audit_done_insert() +RETURNS trigger LANGUAGE plpgsql SECURITY DEFINER SET search_path=pg_catalog AS $body$ +BEGIN + INSERT INTO public.awa_soak_completed_inserts(job_id,run_lease,attempt,queue,writer_shape) + VALUES(NEW.job_id,NEW.run_lease,NEW.attempt,NEW.queue,'done'); + RETURN NEW; +END; +$body$; +CREATE FUNCTION public.awa_soak_audit_receipt_insert() +RETURNS trigger LANGUAGE plpgsql SECURITY DEFINER SET search_path=pg_catalog AS $body$ +BEGIN + INSERT INTO public.awa_soak_completed_inserts(job_id,run_lease,attempt,queue,writer_shape) + SELECT item.job_id,item.run_lease,item.attempt,NEW.queue,'receipt_batch' + FROM unnest(NEW.job_ids,NEW.run_leases,NEW.attempts) AS item(job_id,run_lease,attempt); + RETURN NEW; +END; +$body$; +CREATE TRIGGER awa_soak_audit_done_insert +AFTER INSERT ON __SCHEMA__.done_entries FOR EACH ROW +WHEN (NEW.state='completed'::awa.job_state) +EXECUTE FUNCTION public.awa_soak_audit_done_insert(); +CREATE TRIGGER awa_soak_audit_receipt_insert +AFTER INSERT ON __SCHEMA__.receipt_completion_batches FOR EACH ROW +EXECUTE FUNCTION public.awa_soak_audit_receipt_insert(); +COMMIT; diff --git a/awa/tests/persona_soak/metrics_capture/collector.yaml b/awa/tests/persona_soak/metrics_capture/collector.yaml new file mode 100644 index 000000000..3c9ce77c8 --- /dev/null +++ b/awa/tests/persona_soak/metrics_capture/collector.yaml @@ -0,0 +1,33 @@ +receivers: + otlp: + protocols: + grpc: + endpoint: 0.0.0.0:4317 +processors: + memory_limiter: + check_interval: 1s + limit_mib: 384 + spike_limit_mib: 64 + batch: + timeout: 5s + send_batch_size: 1024 +exporters: + file/raw: + path: /data/metrics.jsonl + append: true + format: json + flush_interval: 1s + prometheus: + endpoint: 0.0.0.0:8889 + enable_open_metrics: true + resource_to_telemetry_conversion: + enabled: true +service: + pipelines: + metrics: + receivers: [otlp] + processors: [memory_limiter, batch] + exporters: [file/raw, prometheus] + telemetry: + logs: + level: info diff --git a/awa/tests/persona_soak/metrics_capture/compose.yaml b/awa/tests/persona_soak/metrics_capture/compose.yaml new file mode 100644 index 000000000..4398943ff --- /dev/null +++ b/awa/tests/persona_soak/metrics_capture/compose.yaml @@ -0,0 +1,18 @@ +name: ${AWA_SOAK_METRICS_PROJECT:?set a unique owned project name} +services: + collector: + image: otel/opentelemetry-collector-contrib:0.115.1 + pull_policy: never + command: ["--config=/etc/otelcol/config.yaml"] + restart: "no" + user: "${AWA_SOAK_METRICS_UID:?set the output owner UID}:${AWA_SOAK_METRICS_GID:?set the output owner GID}" + volumes: + - ./collector.yaml:/etc/otelcol/config.yaml:ro + - ${AWA_SOAK_METRICS_DIR:?set an absolute private capture directory}/collector:/data:rw + ports: + - "127.0.0.1:${AWA_SOAK_METRICS_GRPC_PORT:?set an owned port}:4317" + - "127.0.0.1:${AWA_SOAK_METRICS_PROM_PORT:?set an owned port}:8889" + mem_limit: 512m + cpus: 0.5 + labels: + awa.gate.observer: "true" diff --git a/awa/tests/persona_soak/metrics_capture/run_collector.py b/awa/tests/persona_soak/metrics_capture/run_collector.py new file mode 100644 index 000000000..3d1dd3970 --- /dev/null +++ b/awa/tests/persona_soak/metrics_capture/run_collector.py @@ -0,0 +1,90 @@ +import json +import os +from pathlib import Path +import signal +import subprocess +import sys +import time + +RAW_CAP = 512 * 1024 * 1024 +LOG_CAP = 64 * 1024 * 1024 +STOP = False + + +def request_stop(_signal, _frame): + global STOP + STOP = True + + +def cap_reason(raw_size, log_size): + if raw_size >= RAW_CAP: + return "raw_file_cap" + if log_size >= LOG_CAP: + return "collector_log_cap" + return None + + +def main(): + directory = Path(os.environ["AWA_SOAK_METRICS_DIR"]) + if not directory.is_absolute(): + raise RuntimeError("metrics directory must be absolute") + project = os.environ["AWA_SOAK_METRICS_PROJECT"] + if not project.startswith("awa-gate-") or not all(c.isascii() and (c.islower() or c.isdigit() or c == "-") for c in project): + raise RuntimeError("unique owned awa-gate-* project required") + raw_directory = directory / "collector" + raw_directory.mkdir(mode=0o700, parents=True, exist_ok=False) + os.environ["AWA_SOAK_METRICS_UID"] = str(os.getuid()) + os.environ["AWA_SOAK_METRICS_GID"] = str(os.getgid()) + raw = raw_directory / "metrics.jsonl" + log_path = directory / "collector.log" + receipt = directory / "collector-coverage.json" + signal.signal(signal.SIGINT, request_stop) + signal.signal(signal.SIGTERM, request_stop) + command = ["docker", "compose", "--project-name", project, "--file", str(Path(__file__).with_name("compose.yaml")), "up", "--pull", "never", "--abort-on-container-exit"] + started_ns = time.time_ns() + reason = "collector_exit" + raw_size = 0 + log_size = 0 + with log_path.open("xb") as log: + child = subprocess.Popen(command, stdout=log, stderr=subprocess.STDOUT, start_new_session=True) + try: + while child.poll() is None and not STOP: + raw_size = raw.stat().st_size if raw.exists() else 0 + log_size = log_path.stat().st_size + over_cap = cap_reason(raw_size, log_size) + if over_cap: + reason = over_cap + break + time.sleep(1) + if STOP: + reason = "stop_requested" + finally: + if child.poll() is None: + child.send_signal(signal.SIGINT) + try: + child.wait(timeout=5) + except subprocess.TimeoutExpired: + child.kill() + child.wait(timeout=5) + reason += ":compose_stop_timeout_container_state_unverified" + raw_size = raw.stat().st_size if raw.exists() else 0 + log_size = log_path.stat().st_size + over_cap = cap_reason(raw_size, log_size) + if over_cap: + reason = over_cap + receipt.write_text(json.dumps({ + "project": project, "image": "otel/opentelemetry-collector-contrib:0.115.1", + "image_digest": None, "image_digest_status": "must_be_recorded_before_gate", + "started_ns": started_ns, "stopped_ns": time.time_ns(), + "reason": reason, "compose_exit_code": child.returncode, + "raw_bytes": raw_size, "raw_cap_bytes": RAW_CAP, + "log_bytes": log_size, "log_cap_bytes": LOG_CAP, + "coverage_complete": False, "coverage_status": "raw_transport_and_tail_validation_required", + "cap_status": "exceeded" if over_cap else "not_observed_exceeded", + "cap_overshoot": "one_poll_interval_plus_inflight_exports; no evidence rotated or deleted", + }, indent=2) + "\n") + return 1 if over_cap or reason != "stop_requested" else 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/awa/tests/persona_soak/mod.rs b/awa/tests/persona_soak/mod.rs index bfb4ccb14..a8ece66a1 100644 --- a/awa/tests/persona_soak/mod.rs +++ b/awa/tests/persona_soak/mod.rs @@ -6,6 +6,8 @@ pub mod adminserver; pub mod config; pub mod db; pub mod fleet; +pub mod gate_metrics; +pub mod gate_proof; pub mod ledger; pub mod maintenance_metrics; pub mod oracle; diff --git a/awa/tests/persona_soak/oracle.rs b/awa/tests/persona_soak/oracle.rs index ed5f53366..e11979be0 100644 --- a/awa/tests/persona_soak/oracle.rs +++ b/awa/tests/persona_soak/oracle.rs @@ -171,6 +171,7 @@ impl Oracle { } async fn check_terminal_uniqueness(&mut self) { + super::gate_proof::check_lease_duplicates(&self.shared).await; let schema = schema(&self.shared); let terminal = terminal_cte(&schema); let started = std::time::Instant::now(); @@ -762,14 +763,25 @@ impl Oracle { let mut lost = Vec::new(); let mut lost_after_run = Vec::new(); let mut terminal_in_db = 0usize; + let gate_proof = self.shared.gate_proof.get().is_some(); + let completed = if gate_proof { + "SELECT job_id, 'audit_completed', run_lease FROM public.awa_soak_completed_inserts WHERE job_id = ANY($1)".to_string() + } else { + format!("SELECT b.job_id, 'receipt_completed', b.run_lease + FROM {schema}.receipt_completion_batches c, LATERAL unnest(c.job_ids, c.run_leases) AS b(job_id, run_lease) + WHERE c.job_ids && $1 AND b.job_id = ANY($1)") + }; + let done_filter = if gate_proof { + "AND state <> 'completed'" + } else { + "" + }; for chunk in unresolved.chunks(5000) { let found: Result)>, _> = sqlx::query_as(&format!( "SELECT job_id, string_agg(place, ','), max(terminal_run_lease) FROM ( - SELECT job_id, 'done:' || state::text AS place, run_lease AS terminal_run_lease FROM {schema}.done_entries WHERE job_id = ANY($1) + SELECT job_id, 'done:' || state::text AS place, run_lease AS terminal_run_lease FROM {schema}.done_entries WHERE job_id = ANY($1) {done_filter} UNION ALL SELECT job_id, 'dlq', run_lease FROM {schema}.dlq_entries WHERE job_id = ANY($1) - UNION ALL SELECT b.job_id, 'receipt_completed', b.run_lease - FROM {schema}.receipt_completion_batches c, LATERAL unnest(c.job_ids, c.run_leases) AS b(job_id, run_lease) - WHERE c.job_ids && $1 AND b.job_id = ANY($1) + UNION ALL {completed} UNION ALL SELECT job_id, 'deferred:' || state::text, NULL::bigint FROM {schema}.deferred_jobs WHERE job_id = ANY($1) UNION ALL SELECT job_id, 'ready', NULL::bigint FROM {schema}.ready_entries WHERE job_id = ANY($1) UNION ALL SELECT job_id, 'leased:' || state::text, NULL::bigint FROM {schema}.leases WHERE job_id = ANY($1) @@ -1159,6 +1171,9 @@ mod tests { } async fn drop(self) { + if let Some(proof) = self.shared.gate_proof.get() { + proof.close().await.expect("close proof pool"); + } self.pool.close().await; let admin = db::connect_pool(&self.shared.config.admin_url(), "oracle_cleanup", 1) .await @@ -1428,4 +1443,218 @@ mod tests { ); run.drop().await; } + + #[tokio::test] + async fn gate_handler_return_without_finalization_cannot_gain_terminal_proof() { + let mut run = TestRun::create().await; + super::super::gate_proof::GateProof::install(&run.shared) + .await + .expect("install gate proof"); + run.shared + .record_completed_return(Persona::Priya, &run.claim.job) + .await; + let counts: (i64, i64) = sqlx::query_as( + "SELECT (SELECT count(*) FROM public.awa_soak_handler_returns), + (SELECT count(*) FROM public.awa_soak_completed_inserts)", + ) + .fetch_one(&run.pool) + .await + .expect("read independent witnesses"); + assert_eq!(counts, (1, 0)); + super::super::terminal_proof::observe(&run.shared, &run.pool).await; + assert!(!run + .shared + .ledger + .get(run.claim.job.id) + .expect("record") + .has_durable_terminal()); + run.oracle.final_check(true).await; + assert!(run + .shared + .violations + .lock() + .expect("violations") + .iter() + .any(|row| row.kind == "stuck_job")); + run.drop().await; + } + + #[tokio::test] + async fn gate_completed_audit_survives_compact_and_materialized_terminal_pruning() { + for materialized in [false, true] { + let mut run = TestRun::create().await; + super::super::gate_proof::GateProof::install(&run.shared) + .await + .expect("install gate proof"); + run.shared + .record_completed_return(Persona::Priya, &run.claim.job) + .await; + if materialized { + run.store + .register_callback( + &run.pool, + run.claim.job.id, + run.claim.job.run_lease, + Duration::from_secs(30), + ) + .await + .expect("materialize receipt claim"); + } + run.store + .complete_runtime_batch(&run.pool, std::slice::from_ref(&run.claim)) + .await + .expect("complete"); + let shape: String = sqlx::query_scalar("SELECT writer_shape FROM public.awa_soak_completed_inserts WHERE job_id=$1 AND run_lease=$2") + .bind(run.claim.job.id).bind(run.claim.job.run_lease).fetch_one(&run.pool).await.expect("audit insert"); + assert_eq!( + shape, + if materialized { + "done" + } else { + "receipt_batch" + } + ); + run.store + .reset(&run.pool) + .await + .expect("remove retained product evidence"); + super::super::terminal_proof::observe(&run.shared, &run.pool).await; + assert!(run + .shared + .ledger + .get(run.claim.job.id) + .expect("record") + .has_durable_terminal()); + run.oracle.final_check(true).await; + super::super::gate_proof::reconcile(&run.shared).await; + assert_eq!(run.shared.run.get("gate_completed_unique_pairs"), 1); + assert!(run.shared.violations.lock().expect("violations").is_empty()); + run.drop().await; + } + } + + #[tokio::test] + async fn gate_duplicate_completed_insert_evidence_is_visible_and_fatal() { + let run = TestRun::create().await; + super::super::gate_proof::GateProof::install(&run.shared) + .await + .expect("install gate proof"); + run.store + .complete_runtime_batch(&run.pool, std::slice::from_ref(&run.claim)) + .await + .expect("complete"); + sqlx::query("INSERT INTO public.awa_soak_completed_inserts(job_id,run_lease,attempt,queue,writer_shape) + SELECT job_id,run_lease,attempt,queue,writer_shape FROM public.awa_soak_completed_inserts") + .execute(&run.pool).await.expect("inject duplicate without pair uniqueness"); + super::super::gate_proof::reconcile(&run.shared).await; + assert_eq!(run.shared.run.get("gate_completed_insert_rows"), 2); + assert_eq!(run.shared.run.get("gate_completed_unique_pairs"), 1); + assert!(run + .shared + .violations + .lock() + .expect("violations") + .iter() + .any(|row| row.kind == "duplicate_completed_inserts")); + run.drop().await; + } + + #[tokio::test] + async fn gate_materialized_lease_duplicate_is_visible_without_counting_receipts() { + let run = TestRun::create().await; + super::super::gate_proof::GateProof::install(&run.shared) + .await + .expect("install gate proof"); + run.store + .register_callback( + &run.pool, + run.claim.job.id, + run.claim.job.run_lease, + Duration::from_secs(30), + ) + .await + .expect("materialize receipt claim"); + super::super::gate_proof::check_lease_duplicates(&run.shared).await; + assert!(run.shared.violations.lock().expect("violations").is_empty()); + sqlx::query( + "INSERT INTO awa.leases SELECT (jsonb_populate_record(NULL::awa.leases, + to_jsonb(lease)||jsonb_build_object('lane_seq',lease.lane_seq+1000000))).* + FROM awa.leases AS lease WHERE job_id=$1 AND run_lease=$2", + ) + .bind(run.claim.job.id) + .bind(run.claim.job.run_lease) + .execute(&run.pool) + .await + .expect("inject second materialized lease"); + super::super::gate_proof::check_lease_duplicates(&run.shared).await; + assert!(run + .shared + .violations + .lock() + .expect("violations") + .iter() + .any(|row| row.kind == "duplicate_materialized_leases")); + run.drop().await; + } + + #[tokio::test] + async fn gate_imported_no_events_sample_with_unknown_lease_recovers_pruned_audit() { + let mut run = TestRun::create().await; + assert_eq!( + run.claim + .job + .id + .rem_euclid(super::super::ledger::TERMINAL_PROOF_STRIDE), + 0 + ); + assert!(samples_terminal_proof(run.claim.job.id)); + run.shared.ledger.with( + run.claim.job.id, + || unreachable!("registered"), + |record| { + let mut imported = JobRecord::new( + Persona::ClaimAbandon, + record.queue, + 0, + expect::COMPLETED, + flag::NO_EVENTS, + ); + imported.executions = 1; + imported.max_attempt = run.claim.job.attempt; + *record = imported; + }, + ); + let imported = run + .shared + .ledger + .get(run.claim.job.id) + .expect("imported start"); + assert_eq!(imported.latest_run_lease, 0); + assert!(!imported.has(flag::RETURNED_COMPLETED)); + assert!(!imported.has_durable_terminal()); + super::super::gate_proof::GateProof::install(&run.shared) + .await + .expect("install gate proof"); + run.store + .complete_runtime_batch(&run.pool, std::slice::from_ref(&run.claim)) + .await + .expect("complete actual attempt"); + run.store + .reset(&run.pool) + .await + .expect("remove retained product evidence"); + super::super::terminal_proof::observe(&run.shared, &run.pool).await; + let observed = run + .shared + .ledger + .get(run.claim.job.id) + .expect("observed sample"); + assert_eq!(observed.latest_run_lease, 0); + assert_eq!(observed.terminal_run_lease, Some(run.claim.job.run_lease)); + assert!(observed.has_durable_terminal()); + run.oracle.final_check(true).await; + assert!(!run.shared.oracle_incomplete.load(Ordering::Relaxed)); + assert!(run.shared.violations.lock().expect("violations").is_empty()); + run.drop().await; + } } diff --git a/awa/tests/persona_soak/personas/abandon.rs b/awa/tests/persona_soak/personas/abandon.rs index 6ec671bf4..5f81d1e24 100644 --- a/awa/tests/persona_soak/personas/abandon.rs +++ b/awa/tests/persona_soak/personas/abandon.rs @@ -79,6 +79,7 @@ pub struct AbandonCanaryJob { /// The worker in the child process: records every start in the child ledger and then /// holds the job until the process is killed. struct ChildWorker { + gate_proof: Option, generation: u32, ledger: Mutex, active: Arc, @@ -108,6 +109,15 @@ impl Worker for ChildWorker { let now = self.active.fetch_add(1, Ordering::Relaxed) + 1; self.peak.fetch_max(now, Ordering::Relaxed); tokio::time::sleep(HOLD).await; + if let Some(proof) = &self.gate_proof { + if proof + .returned_completed(&ctx.job, "abandon_child") + .await + .is_err() + { + eprintln!("{}", super::super::gate_proof::ERROR_MARKER); + } + } self.active.fetch_sub(1, Ordering::Relaxed); Ok(JobResult::Completed) } @@ -125,6 +135,10 @@ pub async fn run_child() { return; }; super::super::worker_errors::install(true).expect("child worker error tracing"); + if let Err(error) = super::super::gate_metrics::install("claim_child") { + eprintln!("{}", super::super::gate_metrics::ERROR_MARKER); + panic!("child telemetry setup: {error}"); + } let generation: u32 = generation.parse().expect("generation"); let workers: u32 = workers.parse().expect("workers"); let pool_size: u32 = std::env::var(ENV_POOL) @@ -151,6 +165,13 @@ pub async fn run_child() { .expect("child ledger"); let active = Arc::new(AtomicI64::new(0)); let peak = Arc::new(AtomicI64::new(0)); + let gate_proof = match super::super::gate_proof::GateProof::child().await { + Ok(proof) => proof, + Err(error) => { + eprintln!("{}", super::super::gate_proof::ERROR_MARKER); + panic!("claim child proof setup failed: {error}"); + } + }; let claiming = |deadline_duration: Duration| QueueConfig { max_workers: workers, poll_interval: Duration::from_millis(50), @@ -169,23 +190,36 @@ pub async fn run_child() { .unwrap_or(default), ) }; - let client = timings( - Client::builder(pool) - .queue(QUEUE_PLAIN, claiming(Duration::ZERO)) - .queue(QUEUE_DEADLINE, claiming(DEADLINE)) - .register_worker(ChildWorker { - generation, - ledger: Mutex::new(file), - active: active.clone(), - peak: peak.clone(), - }), - seconds(ENV_HEARTBEAT, DEFAULT_HEARTBEAT_SECONDS), - seconds(ENV_STALENESS, DEFAULT_STALENESS_SECONDS), + let metrics_identity = super::super::gate_metrics::begin_host( + Persona::ClaimAbandon, + &format!("abandon_child_{generation}"), + &format!("soak_abandon_{generation}"), ) - .leader_election_interval(Duration::from_secs(3600)) - .build() - .expect("build child client"); + .unwrap_or_else(|error| { + eprintln!("{}", super::super::gate_metrics::ERROR_MARKER); + panic!("child telemetry identity: {error}") + }); + let client = super::super::gate_metrics::build_client(metrics_identity.as_ref(), || { + timings( + Client::builder(pool) + .queue(QUEUE_PLAIN, claiming(Duration::ZERO)) + .queue(QUEUE_DEADLINE, claiming(DEADLINE)) + .register_worker(ChildWorker { + gate_proof, + generation, + ledger: Mutex::new(file), + active: active.clone(), + peak: peak.clone(), + }), + seconds(ENV_HEARTBEAT, DEFAULT_HEARTBEAT_SECONDS), + seconds(ENV_STALENESS, DEFAULT_STALENESS_SECONDS), + ) + .leader_election_interval(Duration::from_secs(3600)) + .build() + .expect("build child client") + }); client.start().await.expect("start child client"); + super::super::gate_metrics::lifecycle(metrics_identity.as_ref(), "host_started"); println!("READY gen={generation}"); loop { tokio::time::sleep(Duration::from_secs(2)).await; @@ -221,8 +255,8 @@ impl Worker for FinisherWorker { }, ); self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::ClaimAbandon, &ctx.job) + .await; Ok(JobResult::Completed) } } @@ -246,8 +280,8 @@ impl Worker for CanaryWorker { .stats(Persona::ClaimAbandon) .observe("canary_wait_ms", waited); self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::ClaimAbandon, &ctx.job) + .await; Ok(JobResult::Completed) } } @@ -287,6 +321,18 @@ fn spawn_child( "--test-threads=1", ]) .env(ENV_URL, url) + .env( + super::super::gate_proof::ENV_ENABLED, + if shared.gate_proof.get().is_some() { + "1" + } else { + "0" + }, + ) + .env( + super::super::gate_proof::ENV_URL, + super::super::gate_proof::GateProof::owned_url(shared), + ) .env(ENV_GENERATION, generation.to_string()) .env(ENV_LEDGER, ledger) .env(ENV_WORKERS, workers_per_queue.to_string()) @@ -341,6 +387,12 @@ fn spawn_child( } fn absorb_output(shared: &Shared, line: &str) { + if super::super::gate_proof::absorb_error(shared, line) { + return; + } + if super::super::gate_metrics::absorb_output(shared, line) { + return; + } if super::super::worker_errors::absorb_child_marker(line) { return; } diff --git a/awa/tests/persona_soak/personas/alex.rs b/awa/tests/persona_soak/personas/alex.rs index ccd3f1698..a5d97e9a5 100644 --- a/awa/tests/persona_soak/personas/alex.rs +++ b/awa/tests/persona_soak/personas/alex.rs @@ -52,8 +52,8 @@ impl Worker for AlexWorker { return Err(JobError::retryable_msg("interrupted")); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Alex, &ctx.job) + .await; Ok(JobResult::Completed) } } @@ -675,7 +675,7 @@ pub async fn run(shared: Arc) -> Result<(), String> { let diagnostics = connect_pool( &shared.config.database_url, - "soak_alex_diagnostics", + "awa_alex_diagnostics", shared.budget.reserve("alex-diagnostics", 1, 1), ) .await diff --git a/awa/tests/persona_soak/personas/fanout.rs b/awa/tests/persona_soak/personas/fanout.rs index 8b3146300..3eae92400 100644 --- a/awa/tests/persona_soak/personas/fanout.rs +++ b/awa/tests/persona_soak/personas/fanout.rs @@ -157,8 +157,8 @@ impl Worker for ParentWorker { .await?; } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Fanout, &ctx.job) + .await; Ok(JobResult::Completed) } } @@ -177,8 +177,8 @@ impl Worker for ChildWorker { // No lifecycle hooks: a hook per child would add a read per job. let _guard = self.shared.begin_execution(Persona::Fanout, &ctx.job, true); self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Fanout, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/mia.rs b/awa/tests/persona_soak/personas/mia.rs index 0100a2589..3ab67881a 100644 --- a/awa/tests/persona_soak/personas/mia.rs +++ b/awa/tests/persona_soak/personas/mia.rs @@ -85,8 +85,8 @@ impl Worker for MiaWorker { return Err(JobError::retryable_msg("interrupted")); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Mia, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/mod.rs b/awa/tests/persona_soak/personas/mod.rs index df3cfb54c..58500f5eb 100644 --- a/awa/tests/persona_soak/personas/mod.rs +++ b/awa/tests/persona_soak/personas/mod.rs @@ -71,7 +71,26 @@ pub fn tune(builder: ClientBuilder, shared: &Shared) -> ClientBuilder { } } -const DEFAULT_ROTATE_INTERVAL: Duration = Duration::from_millis(1_000); +/// Rotation interval of every ring the run does not set on its own: one second, or four +/// with `AWA_PRESSURE_ROTATE_MULTIPLIER=4`. +fn base_rotate_interval() -> Duration { + super::config::pressure_rotation_interval().expect("valid AWA_PRESSURE_ROTATE_MULTIPLIER") +} + +/// Applies `AWA_PRESSURE_ROTATE_MULTIPLIER` to the queue, lease and claim rings of a +/// runtime, including one in a process of its own. +pub fn pressure_rotation_timings( + builder: ClientBuilder, + storage: QueueStorageConfig, +) -> ClientBuilder { + let interval = base_rotate_interval(); + if interval == Duration::from_secs(1) { + return builder; + } + builder + .queue_storage(storage, interval, interval) + .claim_rotate_interval(interval) +} /// Selects `config` with the run's rotation intervals. A runtime with a storage /// configuration of its own calls this after [`tune`], which would otherwise replace it. @@ -80,21 +99,14 @@ pub fn storage( shared: &Shared, config: QueueStorageConfig, ) -> ClientBuilder { + let base = base_rotate_interval(); builder .queue_storage( config, - shared - .config - .queue_rotate_interval - .unwrap_or(DEFAULT_ROTATE_INTERVAL), - DEFAULT_ROTATE_INTERVAL, - ) - .claim_rotate_interval( - shared - .config - .claim_rotate_interval - .unwrap_or(DEFAULT_ROTATE_INTERVAL), + shared.config.queue_rotate_interval.unwrap_or(base), + base, ) + .claim_rotate_interval(shared.config.claim_rotate_interval.unwrap_or(base)) } /// The timings of [`tune`] that do not depend on the run, for runtimes that live in a @@ -104,6 +116,7 @@ pub fn timings( heartbeat_interval: Duration, heartbeat_staleness: Duration, ) -> ClientBuilder { + let builder = pressure_rotation_timings(builder, QueueStorageConfig::default()); builder .heartbeat_interval(heartbeat_interval) .heartbeat_staleness(heartbeat_staleness) diff --git a/awa/tests/persona_soak/personas/priya.rs b/awa/tests/persona_soak/personas/priya.rs index e674d9a31..5cdab4141 100644 --- a/awa/tests/persona_soak/personas/priya.rs +++ b/awa/tests/persona_soak/personas/priya.rs @@ -36,8 +36,8 @@ impl Worker for PriyaWorker { async fn perform(&self, ctx: &JobContext) -> Result { let _guard = self.shared.begin_execution(Persona::Priya, &ctx.job, true); self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Priya, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/python.rs b/awa/tests/persona_soak/personas/python.rs index 0433f0bba..b51da7c52 100644 --- a/awa/tests/persona_soak/personas/python.rs +++ b/awa/tests/persona_soak/personas/python.rs @@ -74,8 +74,8 @@ impl Worker for SharedQueueWorker { return Err(JobError::retryable_msg("interrupted")); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Python, &ctx.job) + .await; Ok(JobResult::Completed) } } @@ -130,6 +130,19 @@ fn spawn_process( .to_string(), ) .env("SOAK_ROLE", role) + .env("SOAK_PG_APPLICATION_NAME", application_name) + .env( + super::super::gate_proof::ENV_ENABLED, + if shared.gate_proof.get().is_some() { + "1" + } else { + "0" + }, + ) + .env( + super::super::gate_proof::ENV_URL, + super::super::gate_proof::GateProof::owned_url(shared), + ) .env( "SOAK_DRAIN", if shared.load_stop.is_stopped() { @@ -176,9 +189,27 @@ fn spawn_process( let shared = shared.clone(); let probe_phase = probe_phase.clone(); let application_name = application_name.to_string(); + let instrumented_output = shared.gate_proof.get().is_some() + || std::env::var_os(super::super::gate_metrics::ENV_ENDPOINT).is_some(); + let output_guard = + instrumented_output.then(super::super::worker_errors::child_output_guard); tokio::spawn(async move { + let _output_guard = output_guard; let mut lines = BufReader::new(stream).lines(); - while let Ok(Some(line)) = lines.next_line().await { + loop { + let line = match lines.next_line().await { + Ok(Some(line)) => line, + Ok(None) => break, + Err(error) => { + if instrumented_output { + shared.incomplete( + format!("Python instrumentation output read failed: {error}"), + vec![], + ); + } + break; + } + }; if let (Some(phase), Some(marker)) = (&probe_phase, Phase::marker(&line)) { // A close marker alone does not prove migrate-and-query // reached readiness. IDLE also follows that completed call. @@ -196,6 +227,12 @@ fn spawn_process( /// Turns the interesting stdout lines of the Python process into report counters. fn absorb_output(shared: &Shared, line: &str) { + if super::super::gate_proof::absorb_error(shared, line) { + return; + } + if super::super::gate_metrics::absorb_output(shared, line) { + return; + } let stats = shared.stats(Persona::Python); let field = |name: &str| { line.split_whitespace() @@ -501,7 +538,7 @@ async fn migrate_probe(shared: &Arc, python: &PathBuf, ledger_path: &Pat }; let pool = match super::super::db::connect_pool( &shared.config.database_url, - "soak_python_probe_watch", + "awa_python_probe_watch", 1, ) .await @@ -639,7 +676,7 @@ pub async fn run(shared: Arc) -> Result<(), String> { shared.note("python", format!("{} started; queues {QUEUE_WORK}, {QUEUE_DEADLINE}, {QUEUE_SHARED} (shared with a Rust runtime)", python.display())); let tail_pool = - super::super::db::connect_pool(&shared.config.database_url, "soak_python_tail", 1) + super::super::db::connect_pool(&shared.config.database_url, "awa_python_tail", 1) .await .map_err(|error| error.to_string())?; let mut tail_tick = 0u64; @@ -798,7 +835,7 @@ async fn check_rolled_back(shared: &Arc, ids: &HashSet) -> Result<( .queue_storage_schema .clone() .unwrap_or_else(|| "awa".into()); - let pool = super::super::db::connect_pool(&shared.config.database_url, "soak_python_check", 1) + let pool = super::super::db::connect_pool(&shared.config.database_url, "awa_python_check", 1) .await .map_err(|error| error.to_string())?; let ids: Vec = ids.iter().copied().collect(); diff --git a/awa/tests/persona_soak/personas/sam.rs b/awa/tests/persona_soak/personas/sam.rs index da0a2e12f..6ea0892db 100644 --- a/awa/tests/persona_soak/personas/sam.rs +++ b/awa/tests/persona_soak/personas/sam.rs @@ -5,7 +5,7 @@ use super::super::config::Persona; use super::super::db::{connect_pool, ClientFactory}; use super::super::fleet::Fleet; -use super::super::ledger::{expect, flag}; +use super::super::ledger::expect; use super::super::rng::Rng; use super::super::shared::Shared; use super::{attach_events, backoff, queue, register_rows, storage, tune}; @@ -81,8 +81,8 @@ impl Worker for SamWorker { return Err(JobError::retryable_msg("interrupted")); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Sam, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/shardops.rs b/awa/tests/persona_soak/personas/shardops.rs index a462c632b..53a83af2b 100644 --- a/awa/tests/persona_soak/personas/shardops.rs +++ b/awa/tests/persona_soak/personas/shardops.rs @@ -12,7 +12,6 @@ use super::super::config::Persona; use super::super::db::{connect_pool, ClientFactory}; use super::super::fleet::Fleet; -use super::super::ledger::flag; use super::super::registry::QueueInfo; use super::super::rng::Rng; use super::super::roles; @@ -74,8 +73,8 @@ impl Worker for ShardOpsWorker { ))); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::ShardOps, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/tom.rs b/awa/tests/persona_soak/personas/tom.rs index 3f3b5ede3..904a131e8 100644 --- a/awa/tests/persona_soak/personas/tom.rs +++ b/awa/tests/persona_soak/personas/tom.rs @@ -5,7 +5,7 @@ use super::super::config::Persona; use super::super::db::{connect_pool, ClientFactory}; use super::super::fleet::Fleet; -use super::super::ledger::{expect, flag, JobRecord}; +use super::super::ledger::{expect, JobRecord}; use super::super::rng::Rng; use super::super::shared::Shared; use super::{attach_events, backoff, register_rows, tune}; @@ -48,8 +48,8 @@ impl Worker for TomWorker { return Err(JobError::retryable_msg("interrupted")); } self.shared - .ledger - .mark(ctx.job.id, flag::RETURNED_COMPLETED); + .record_completed_return(Persona::Tom, &ctx.job) + .await; Ok(JobResult::Completed) } } diff --git a/awa/tests/persona_soak/personas/ui.rs b/awa/tests/persona_soak/personas/ui.rs index 9a47e4e98..39f8fc926 100644 --- a/awa/tests/persona_soak/personas/ui.rs +++ b/awa/tests/persona_soak/personas/ui.rs @@ -649,7 +649,7 @@ pub async fn run_impatient(shared: Arc) -> Result<(), String> { let http = Arc::new(Http::new(&shared, persona)); let sampler_pool = connect_pool( &shared.config.database_url, - "soak_ui_sampler", + "awa_ui_sampler", shared.budget.reserve("ui-sampler", 1, 1), ) .await diff --git a/awa/tests/persona_soak/python/soak_python.py b/awa/tests/persona_soak/python/soak_python.py index b5fe642f8..b3d6e0411 100644 --- a/awa/tests/persona_soak/python/soak_python.py +++ b/awa/tests/persona_soak/python/soak_python.py @@ -74,6 +74,23 @@ class PySharedJob: started = 0 enqueued = 0 errors = 0 +proof_pool = None +PROOF_ERROR_MARKER = "AWA_SOAK_GATE_PROOF_INCOMPLETE" +PROOF_WRITE_TIMEOUT_SECONDS = 5.0 + + +async def record_completed_return(job): + if proof_pool is None: + return + try: + await asyncio.wait_for(proof_pool.execute( + "INSERT INTO public.awa_soak_handler_returns(job_id,run_lease,queue,persona,outcome) " + "VALUES($1,$2,$3,'python_child','completed')", + job.id, job.run_lease, job.queue, + ), timeout=PROOF_WRITE_TIMEOUT_SECONDS) + except Exception: + print(PROOF_ERROR_MARKER, file=sys.stderr, flush=True) + async def handle(job): @@ -124,6 +141,7 @@ async def handle(job): await asyncio.sleep(args.work_ms / 1000) else: await asyncio.sleep(args.work_ms / 1000) + await record_completed_return(job) return None except Exception: raise @@ -307,11 +325,46 @@ async def exit_with_parent(): os._exit(1) +def init_gate_metrics(): + endpoint = os.environ.get("AWA_SOAK_METRICS_ENDPOINT") + if endpoint is None: + return + service = f"awa-soak-python-{ROLE}-{os.getpid()}-{time.time_ns()}" + try: + if not awa.init_telemetry(endpoint, service, export_interval_ms=5000): + raise RuntimeError("telemetry provider already installed") + except Exception: + print("AWA_SOAK_METRICS_INCOMPLETE", file=sys.stderr, flush=True) + raise + print("AWA_SOAK_METRICS " + json.dumps({ + "kind": "initialized", "process_role": f"python/{ROLE}", "pid": os.getpid(), + "utc": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()), + "service_name": service, "application": os.environ.get("SOAK_PG_APPLICATION_NAME", "unassigned"), + "export_interval_ms": 5000, "delivery": "unverified", "final_flush": "not_attempted", + "tail": "potentially_incomplete", "baseline_prune_errors": "unavailable", + }, separators=(",", ":")), flush=True) + + async def main(): + init_gate_metrics() asyncio.create_task(exit_with_parent()) if ROLE == "migrate_probe": await migrate_probe_main() return + if os.environ.get("AWA_SOAK_GATE_PROOF", "0") == "1": + global proof_pool + try: + if not hasattr(awa.Job, "run_lease"): + raise RuntimeError("gate proof requires the common run_lease observation getter") + import asyncpg + proof_pool = await asyncio.wait_for(asyncpg.create_pool( + os.environ["AWA_SOAK_GATE_PROOF_URL"], min_size=1, max_size=1, + command_timeout=PROOF_WRITE_TIMEOUT_SECONDS, + server_settings={"application_name": "awa_gate_proof_python", "statement_timeout": str(int(PROOF_WRITE_TIMEOUT_SECONDS * 1000))}, + ), timeout=2.0) + except Exception: + print(PROOF_ERROR_MARKER, file=sys.stderr, flush=True) + raise # A chaos restart can still be migrating when the load ends. Remember the # drain request before startup awaits, then start workers without producers. stop = asyncio.Event() @@ -324,6 +377,14 @@ async def main(): await migrate_and_probe(client, "startup") client.task(PyJob, kind="py_job", queue=QUEUE_WORK)(handle) client.task(PySharedJob, kind="py_shared_job", queue=QUEUE_SHARED)(handle) + rotation_factor = (os.environ.get("AWA_PRESSURE_ROTATE_MULTIPLIER", "1").strip() or "1") + if rotation_factor not in ("1", "4"): + raise ValueError("AWA_PRESSURE_ROTATE_MULTIPLIER must be 1 or 4") + rotation_kwargs = {} if rotation_factor == "1" else { + "queue_storage_queue_rotate_interval_ms": 4000, + "queue_storage_lease_rotate_interval_ms": 4000, + "queue_storage_claim_rotate_interval_ms": 4000, + } await client.start( [ {"name": QUEUE_WORK, "max_workers": WORK_WORKERS}, @@ -335,6 +396,7 @@ async def main(): heartbeat_rescue_interval_ms=int(RESCUE_INTERVAL_MS or 3000), deadline_rescue_interval_ms=int(RESCUE_INTERVAL_MS or 2000), promote_interval_ms=250, + **rotation_kwargs, ) # The deadline queue serves a second kind through the same handler. print(f"READY pid={os.getpid()}", flush=True) diff --git a/awa/tests/persona_soak/registry.rs b/awa/tests/persona_soak/registry.rs index 2eca256f3..98eaf1703 100644 --- a/awa/tests/persona_soak/registry.rs +++ b/awa/tests/persona_soak/registry.rs @@ -136,42 +136,72 @@ impl Drop for InFlightGuard { #[cfg(test)] mod tests { - use super::QueueRegistry; - use crate::persona_soak::config::Persona; - use std::sync::mpsc; - use std::sync::Arc; - use std::time::Duration; + use super::*; + use crate::ci_timing::scaled_timeout; + use std::sync::{mpsc, Barrier}; + use std::time::{Duration, Instant}; #[test] - fn lookups_and_registrations_do_not_deadlock() { + fn concurrent_registration_and_striped_lookup_complete() { let registry = Arc::new(QueueRegistry::default()); - registry.register("awa_soak_registry_0", Persona::Mia, false); - let (done_tx, done_rx) = mpsc::channel(); - let registering = { + let seed = registry.register("seed", Persona::Mia, true); + assert!(Arc::ptr_eq(&seed, ®istry.get("seed#7").unwrap())); + assert!(registry.get("seed#bad").is_none()); + assert!(registry.get("missing").is_none()); + let duplicate = registry.register("seed", Persona::Tom, false); + assert!(Arc::ptr_eq(&seed, &duplicate)); + assert!(duplicate.persona == Persona::Mia && duplicate.rate_limited); + let barrier = Arc::new(Barrier::new(9)); + let (done, completed) = mpsc::channel(); + let mut threads = Vec::new(); + for worker in 0..8 { let registry = registry.clone(); - let done_tx = done_tx.clone(); - std::thread::spawn(move || { - for index in 1..20_000 { - registry.register(&format!("awa_soak_registry_{index}"), Persona::Mia, false); + let seed = seed.clone(); + let barrier = barrier.clone(); + let done = done.clone(); + threads.push(std::thread::spawn(move || { + barrier.wait(); + if worker < 4 { + for number in 0..2_000 { + let name = format!("queue-{worker}-{number}"); + let queue = registry.register(&name, Persona::Tom, false); + assert!(Arc::ptr_eq(&queue, ®istry.get(&name).unwrap())); + assert!(Arc::ptr_eq( + &queue, + ®istry.get(&format!("{name}#2")).unwrap() + )); + assert!(Arc::ptr_eq( + &queue, + ®istry.by_index(queue.index).unwrap() + )); + } + } else { + for number in 0..20_000 { + assert!(Arc::ptr_eq(&seed, ®istry.get("seed#3").unwrap())); + let name = format!("queue-{}-{}", number % 4, number % 2_000); + if let Some(queue) = registry.get(&name) { + assert_eq!(queue.name, name); + assert!(Arc::ptr_eq( + &queue, + ®istry.by_index(queue.index).unwrap() + )); + } + } } - let _ = done_tx.send(()); - }) - }; - let looking_up = { - let registry = registry.clone(); - std::thread::spawn(move || { - for _ in 0..200_000 { - assert!(registry.get("awa_soak_registry_0#1").is_some()); - } - let _ = done_tx.send(()); - }) - }; - for _ in 0..2 { - done_rx - .recv_timeout(Duration::from_secs(30)) - .expect("register and get finish without deadlocking"); + done.send(()).unwrap(); + })); + } + drop(done); + barrier.wait(); + let deadline = Instant::now() + scaled_timeout(Duration::from_secs(30)); + for _ in 0..8 { + completed + .recv_timeout(deadline.saturating_duration_since(Instant::now())) + .expect("concurrent register/get must complete before the deadline"); + } + for thread in threads { + thread.join().unwrap(); } - registering.join().unwrap(); - looking_up.join().unwrap(); + assert_eq!(registry.all().len(), 8_001); } } diff --git a/awa/tests/persona_soak/report.rs b/awa/tests/persona_soak/report.rs index d309bfc94..210d2e034 100644 --- a/awa/tests/persona_soak/report.rs +++ b/awa/tests/persona_soak/report.rs @@ -201,6 +201,8 @@ pub fn write(shared: &Shared, outcome: &Outcome) -> std::io::Result<()> { "verdict": if violations.iter().any(|violation| violation.kind != "oracle_incomplete") { "fail" } else if shared.oracle_incomplete.load(std::sync::atomic::Ordering::Relaxed) { "inconclusive" } else { "pass" }, "terminal_proof_sample_stride": super::ledger::TERMINAL_PROOF_STRIDE, + "gate_proof_enabled": shared.gate_proof.get().is_some(), + "gate_proof_policy": "when enabled: full unpruned committed completed-pair counts; per-job eventful/NO_EVENTS sample policy unchanged; handler returns are execution evidence; counts do not waive quiescence, caps or other violations", "oracle_complete": !shared.oracle_incomplete.load(std::sync::atomic::Ordering::Relaxed), "seed": shared.config.seed, "personas": shared.config.personas.iter().map(|p| p.name()).collect::>(), diff --git a/awa/tests/persona_soak/run.rs b/awa/tests/persona_soak/run.rs index 849b94321..b1fa7d678 100644 --- a/awa/tests/persona_soak/run.rs +++ b/awa/tests/persona_soak/run.rs @@ -18,7 +18,11 @@ const HEADROOM: u32 = 14; pub async fn run_soak(config: SoakConfig) -> Result, String> { let worker_errors = super::worker_errors::install(false)?; - let maintenance_metrics = super::maintenance_metrics::install(); + super::gate_metrics::install("parent")?; + // OTLP capture, when on, owns the global meter provider, and its collector also + // receives the maintenance metrics, so the in-memory capture is only for runs without it. + let maintenance_metrics = + (!super::gate_metrics::active()).then(super::maintenance_metrics::install); eprintln!( "{}: preparing database {}", report::HEADER, @@ -57,6 +61,9 @@ pub async fn run_soak(config: SoakConfig) -> Result, String> { )); } let shared = Shared::new(config, info, budget); + if super::gate_proof::enabled_from_env()? { + super::gate_proof::GateProof::install(&shared).await?; + } // The UI personas talk to the real admin server, run as a child process. let ui_personas = [ @@ -242,6 +249,13 @@ pub async fn run_soak(config: SoakConfig) -> Result, String> { server.stop(); } super::worker_errors::reconcile(&shared, &worker_errors).await; + super::gate_proof::reconcile(&shared).await; + if let Some(proof) = shared.gate_proof.get() { + if let Err(error) = proof.close().await { + shared.incomplete(error, vec![]); + } + } + super::gate_metrics::reconcile(&shared); let outcome = Outcome { quiesced, elapsed_seconds: shared.started.elapsed().as_secs_f64(), @@ -251,7 +265,10 @@ pub async fn run_soak(config: SoakConfig) -> Result, String> { if let Err(error) = report::write(&shared, &outcome) { eprintln!("could not write the report: {error}"); } - if let Err(error) = maintenance_metrics.write(&shared.config.report_dir) { + if let Some(Err(error)) = maintenance_metrics + .as_ref() + .map(|capture| capture.write(&shared.config.report_dir)) + { eprintln!("could not write the maintenance metrics: {error}"); } oracle_pool.close().await; diff --git a/awa/tests/persona_soak/shared.rs b/awa/tests/persona_soak/shared.rs index 2bd038081..4cca81221 100644 --- a/awa/tests/persona_soak/shared.rs +++ b/awa/tests/persona_soak/shared.rs @@ -11,7 +11,7 @@ use awa::{JobRow, UntypedJobEvent}; use serde::Serialize; use std::collections::{BTreeMap, HashMap}; use std::sync::atomic::{AtomicBool, AtomicI64, Ordering}; -use std::sync::{Arc, Mutex}; +use std::sync::{Arc, Mutex, OnceLock}; use std::time::Instant; #[derive(Debug, Clone, Serialize)] @@ -110,6 +110,7 @@ pub struct Shared { pub info: ServerInfo, pub started: Instant, pub ledger: Ledger, + pub gate_proof: OnceLock, pub queues: QueueRegistry, pub budget: Budget, pub load_stop: Stop, @@ -149,6 +150,7 @@ impl Shared { info, started: Instant::now(), ledger: Ledger::new(), + gate_proof: OnceLock::new(), queues: QueueRegistry::default(), budget, load_stop: Stop::new(), @@ -289,6 +291,21 @@ impl Shared { /// Records the start of a handler. Hold the returned guard for the duration of /// `perform`; dropping it, including when the runtime is killed, ends the execution. + pub async fn record_completed_return(&self, persona: Persona, job: &JobRow) { + if let Some(proof) = self.gate_proof.get() { + let started = Instant::now(); + if let Err(error) = proof.returned_completed(job, persona.name()).await { + self.incomplete(error, vec![]); + self.run.add("gate_handler_return_write_failures", 1); + } + self.run.add( + "gate_handler_return_write_us", + started.elapsed().as_micros().min(i64::MAX as u128) as i64, + ); + } + self.ledger.mark(job.id, flag::RETURNED_COMPLETED); + } + pub fn begin_execution( self: &Arc, persona: Persona, diff --git a/awa/tests/persona_soak/terminal_proof.rs b/awa/tests/persona_soak/terminal_proof.rs index 1e9773afc..9eaf3774f 100644 --- a/awa/tests/persona_soak/terminal_proof.rs +++ b/awa/tests/persona_soak/terminal_proof.rs @@ -26,6 +26,10 @@ pub async fn run(shared: Arc, pool: PgPool, stop: Stop) { /// input/result counts and a two-second statement timeout. NO_EVENTS keeps its /// immutable sample; neither a returned handler nor a missed query proves a commit. pub async fn observe(shared: &Shared, pool: &PgPool) { + if shared.gate_proof.get().is_some() { + super::gate_proof::observe(shared).await; + return; + } let schema = shared.info.queue_storage_schema.as_deref().unwrap_or("awa"); let mut pending = Vec::new(); shared.ledger.for_each(|id, record| { diff --git a/awa/tests/persona_soak/worker_errors.rs b/awa/tests/persona_soak/worker_errors.rs index 89dfb5070..7f292f16a 100644 --- a/awa/tests/persona_soak/worker_errors.rs +++ b/awa/tests/persona_soak/worker_errors.rs @@ -28,10 +28,14 @@ pub struct WorkerErrors { #[derive(Default)] struct ErrorFields { invalid_ready_body: bool, + prune_ring: Option<&'static str>, } impl Visit for ErrorFields { fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + self.prune_ring = super::gate_metrics::prune_ring(value); + } if matches!(field.name(), "error" | "message") { self.invalid_ready_body |= value.contains(MISSING_READY) || value.contains(AMBIGUOUS_READY); @@ -40,10 +44,12 @@ impl Visit for ErrorFields { fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { if matches!(field.name(), "error" | "message") { - self.invalid_ready_body |= { - let formatted = format!("{value:?}"); - formatted.contains(MISSING_READY) || formatted.contains(AMBIGUOUS_READY) - }; + let formatted = format!("{value:?}"); + if field.name() == "message" { + self.prune_ring = super::gate_metrics::prune_ring(&formatted); + } + self.invalid_ready_body |= + formatted.contains(MISSING_READY) || formatted.contains(AMBIGUOUS_READY); } } } @@ -61,6 +67,11 @@ impl Layer for ErrorLayer { } let mut fields = ErrorFields::default(); event.record(&mut fields); + if *event.metadata().level() == tracing::Level::ERROR { + if let Some(ring) = fields.prune_ring { + super::gate_metrics::prune_error(ring); + } + } if fields.invalid_ready_body { self.evidence .invalid_ready_body diff --git a/docs/test-plan.md b/docs/test-plan.md index 30e96fc3a..778c0cbcb 100644 --- a/docs/test-plan.md +++ b/docs/test-plan.md @@ -376,11 +376,59 @@ Environment: | `AWA_SOAK_PG_LOG` / `AWA_SOAK_PG_CONTAINER` / `AWA_SOAK_PG_CONTAINER_LOG` | where to read the server log for the crash scan: a file on this host, or a Docker container (with an optional log path inside it, otherwise `docker logs`) | | `AWA_SOAK_REPORT_DIR` | where `report.md`, `report.json` and, for a failed run, `reproducer.md` are written |; `maintenance-metrics.jsonl` holds the `awa.maintenance.*` metrics of the in-process runtimes as cumulative data points exported every 10 s (prune and rotate attempts by ring and outcome, branch durations and overruns, promotion lane contention) | `AWA_SOAK_STALL_SECONDS`, `AWA_SOAK_PROMOTION_OVERDUE_SECONDS`, `AWA_SOAK_CHAOS_SLACK_SECONDS` | oracle thresholds | +| `AWA_SOAK_GATE_PROOF` | default `0`; `1` adds logged handler-return and committed-completion witnesses that survive terminal pruning | +| `AWA_SOAK_METRICS_ENDPOINT`, `AWA_SOAK_METRICS_DIR` | optional OTLP gRPC endpoint and absolute output directory for per-process metric receipts | +| `AWA_PRESSURE_ROTATE_MULTIPLIER` | pressure comparison setting: `1` (default) or `4`; scales the harness's queue, lease and claim rotation intervals; keeps configured generation rates unchanged. `AWA_SOAK_QUEUE_ROTATE_MS` and `AWA_SOAK_CLAIM_ROTATE_MS` take precedence for their rings, and the interval they fix an unset ring at becomes 4000 with `4` | The report records the engine, server version, `max_connections`, connections at start and the per-persona connection budget. A failed run leaves `reproducer.md` with the seed, personas and duration, the violating rows, the timeline around each violation and the relevant server log excerpt. `scripts/persona-soak.sh` runs the engine matrix (`postgres:17`, `postgres:18`, and an assert-enabled PostgreSQL 18 image) in private containers on separate ports and removes them afterwards. After-exit retained-session findings require a successful `CLOSED` acknowledgement and a valid final session observation. Forced or unproven exits remain incomplete evidence. Pool-budget and idle-transaction checks after readiness remain independent. +### Optional completion proof and metric capture + +`AWA_SOAK_GATE_PROOF=1` installs audit triggers in the disposable soak database. +The logged audit heaps retain handler returns and committed completion inserts +independently of terminal pruning. The oracle checks duplicate completion and +materialized lease identities. A handler return alone does not prove completion; +a stale attempt may return without committing. Witness failures make the oracle +incomplete. The probes add SQL, WAL, locks and up to 18 parent connections plus +one connection per Rust or Python child. Python proof capture also needs `asyncpg` +and a binding exposing the read-only `Job.run_lease` property. + +Metric capture uses a five-second cumulative OTLP export interval and emits +process/runtime identity receipts. It does not wait for a final export when a +runtime exits or is killed. Validate transport delivery and missing tails against +the collector output before comparing metric totals. The collector wrapper in +`awa/tests/persona_soak/metrics_capture/run_collector.py` requires Docker Compose, +a locally available `otel/opentelemetry-collector-contrib:0.115.1` image, and these +variables in addition to `AWA_SOAK_METRICS_DIR`: + +- `AWA_SOAK_METRICS_PROJECT`: a unique `awa-gate-*` project name. +- `AWA_SOAK_METRICS_GRPC_PORT`: an available localhost OTLP port matching + `AWA_SOAK_METRICS_ENDPOINT`. +- `AWA_SOAK_METRICS_PROM_PORT`: an available localhost Prometheus port. + +Record the collector image digest separately. The wrapper writes raw metric +JSON, a collector log and a coverage receipt. Its size caps stop capture; they do +not rotate or discard evidence, and the receipt requires delivery validation. + +`bulk_rescue_test` installs the same completion witness for its 50,000-claim +abandoned backlog, so it checks every committed recovery and live completion +against the attempts its handlers ran even after prune has removed them. + +The ignored `operation_lock_footprint_test` target holds two diagnostics. A +controlled operation fixture samples 26 public operations with maintenance +disabled and default ring sizes; its `OP_START` and `OP_END` JSON markers +bracket only the API call, and backend identity checks and result assertions +run outside that window. Require the fixture's separate assertions and PASS +markers before treating an API-success marker as a validated operation. A +second test logs the actual plan of a 10,000-job bulk failed-to-DLQ move. Both +create disposable databases using `DATABASE_URL` and require a role with +`CREATEDB`; run them with +`cargo test -p awa --test operation_lock_footprint_test -- --ignored --nocapture`. +Their probes affect the measured workload; use them as diagnostics rather than +latency acceptance benchmarks. + ## Running Tests ```bash diff --git a/scripts/lock-pressure/README.md b/scripts/lock-pressure/README.md new file mode 100644 index 000000000..a8c387677 --- /dev/null +++ b/scripts/lock-pressure/README.md @@ -0,0 +1,38 @@ +# Lock pressure diagnostics + +Experimental source helpers for awa maintenance traces and PostgreSQL JSON logs. These are individual measurement tools; a complete campaign runner and release acceptance criteria are not included. Python 3.10+ is required. Source and archive verification use assertions; those helpers reject Python's `-O` mode. + +Run the synthetic parser controls from any directory: + +```sh +python scripts/lock-pressure/check_parsers.py +``` + +Replay closed log files with a caller-supplied JSON source list. Paths are resolved relative to the source-list file; `original_path` supplies the original suffix and provenance identity. Use `.json` for PostgreSQL JSON log records and set `gzip: true` for compressed input. The output directory must be new. + +```json +[{"path":"server.json","original_path":"server.json","source_key":"server:1","gzip":false}] +``` + +```sh +python scripts/lock-pressure/replay.py --sources sources.json --out analysis +python scripts/lock-pressure/prune_calls.py run-directory +``` + +`replay.py` writes `utility-events.jsonl`, `utility-summary.json` and `replay.json`. The default event-output cap is 256 MiB (`--event-cap-bytes`). That cap does not bound total input size, summary memory, or provenance memory; choose bounded input files. Invalid JSON and partial final lines are recorded. Counts describe direct SQL commands: successful statements do not prove transaction commit or internal lock-request counts. `prune_calls.py` scans `run.log` and top-level `*.stderr`/`*.stdout`, caps total input at 64 MiB (`--cap-bytes`), and writes `prune-call-ledger.json`; missing start/end pairs stay incomplete. Both tools write local outputs and preserve input files. + +`evidence.py` exposes `replay`, `compare_feed_replay` and the rotation-aware `InodePump`. `archive.py` exposes read-only `replay_sources(raw, archive_dir, receipts, stream_index=None)`, validating compressed and decompressed hashes before selecting archived streams and suppressing duplicate raw copies. Receipts retain their recorded paths; archived packet relocation needs an explicit caller mapping. Live archival and process-closure probes are excluded because their guarantees depend on the capture environment. A replay call alone does not establish producer closure. + +`slot_observer.py` exposes `observe(connection, phase, exact_rows=False, budget_seconds=2.0)` for an exclusively owned, idle psycopg autocommit connection. Install psycopg separately when integrating it. It reads the adjacent `catalog.sql`, targets the default `awa` schema, temporarily sets 100 ms statement/lock timeouts and restores the prior values. The two-second budget controls admission of additional exact-count queries; it is not a hard client or network deadline. Transport failures propagate and require closing/resetting the connection. Keep metadata and checkpoint policies identical between compared variants. Row estimates, exact physical rows, member counts, stale generations and unknown observations remain separate; physical rows across families are not unique jobs. + +`relation-lock-snapshot.sql` samples relation-lock rows for the controlled `operation_lock_footprint_test` fixture. Bind its application-name list as `$1::text[]`; it restricts database names to `awa_footprint_%`. A caller must supply the polling interval and observation limits. Match database OID, backend start and the fixture's operation markers before attributing a sample. Activity and lock observations are not atomic, and sampled maxima are lower bounds on true peaks. The fixture and SQL do not set a one-millisecond sampling interval or change prune's lock timeout. + +Generate a prune tracing patch without editing a checkout: + +```sh +python scripts/lock-pressure/prepare_overlay.py --repository . --variant baseline=REF --variant candidate=OTHER_REF --out new-overlays +``` + +`prepare_overlay.py` resolves each ref to a commit, reads `awa-model/src/queue_storage.rs`, and writes a patch and source-hash/proof manifest beneath a new output directory. `prune_trace.rs` is the inserted template. Source anchors and reversible wrapper checks reject incompatible source layouts; arbitrary future versions are not supported. Generated patches are uncompiled and unrun until separately reviewed and validated. No runtime source is changed by generation. The overlay adds logging and timing work, so measured variants need identical instrumentation. Log writes can fail silently; missing events are unknown. Initial lock failures, later stages and transaction commits remain distinct in the derived ledger. + +The included 41-record fixture is synthetic. Controls compare replayed event bytes with direct parsing, reject duplicated/missing provenance events and corrupt archives, verify raw/archive deduplication, and retain invalid/partial-line diagnostics. They do not run a database, compile Rust, establish live closure, or measure campaign performance. diff --git a/scripts/lock-pressure/archive.py b/scripts/lock-pressure/archive.py new file mode 100644 index 000000000..e5949750e --- /dev/null +++ b/scripts/lock-pressure/archive.py @@ -0,0 +1,40 @@ +import gzip,hashlib,json,pathlib + +if not __debug__: + raise RuntimeError('lock-pressure evidence verification requires Python assertions') +CHUNK=1024*1024 + +def sha(path): + h=hashlib.sha256();size=0 + with pathlib.Path(path).open('rb') as f: + for b in iter(lambda:f.read(CHUNK),b''):h.update(b);size+=len(b) + return h.hexdigest(),size + +def receipt_rows(path): + with pathlib.Path(path).open() as f: + for line in f:yield json.loads(line) + +def replay_sources(raw,archive_dir,receipts,stream_index=None): + index={s['source_key']:s for s in (stream_index or [])} + verified={};unlinked=set() + if pathlib.Path(receipts).exists(): + for row in receipt_rows(receipts): + if row['phase']=='verified_before_unlink':verified[row['source_key']]=row + elif row['phase']=='unlinked':unlinked.add(row['source_key']) + sources=[];covered=set() + for key,row in verified.items(): + archive=pathlib.Path(row['archive_path']);assert sha(archive)==(row['compressed_sha256'],row['compressed_bytes']) + with gzip.open(archive,'rb') as f: + h=hashlib.sha256();size=0 + for b in iter(lambda:f.read(CHUNK),b''):h.update(b);size+=len(b) + assert (h.hexdigest(),size)==(row['source_sha256'],row['original_bytes']) + sources.append({**row,'path':str(archive),'gzip':True});covered.add(key) + # A crash after durable receipt but before unlink leaves both copies; replay only the verified archive. + for path in pathlib.Path(raw).rglob('*'): + if not path.is_file() or path.suffix not in ('.json','.internal','.log'):continue + st=path.stat() + matches=[s for s in (stream_index or []) if s['path']==str(path) and s['device']==st.st_dev and s['inode']==st.st_ino] + key=matches[-1]['source_key'] if matches else f'{st.st_dev}:{st.st_ino}' + if key in covered:continue + sources.append({**index.get(key,{}),'source_key':key,'original_path':index.get(key,{}).get('original_path',str(path)),'path':str(path),'gzip':False,'ordinal':index.get(key,{}).get('ordinal',10**12+st.st_mtime_ns)}) + return sorted(sources,key=lambda s:s['ordinal']) diff --git a/scripts/lock-pressure/catalog.sql b/scripts/lock-pressure/catalog.sql new file mode 100644 index 000000000..907be2510 --- /dev/null +++ b/scripts/lock-pressure/catalog.sql @@ -0,0 +1,38 @@ +WITH rings AS ( + SELECT 'queue'::text AS family, 'ready_slot'::text AS partition_key, + s.current_slot, s.generation AS ring_generation, s.slot_count, + slots.slot, slots.generation AS slot_generation + FROM awa.queue_ring_state s CROSS JOIN awa.queue_ring_slots slots WHERE s.singleton AND slots.generation>=0 AND slots.generation<=s.generation + UNION ALL + SELECT 'lease', 'lease_slot', s.current_slot, s.generation, s.slot_count, + slots.slot, slots.generation + FROM awa.lease_ring_state s CROSS JOIN awa.lease_ring_slots slots WHERE s.singleton AND slots.generation>=0 AND slots.generation<=s.generation + UNION ALL + SELECT 'claim', 'claim_slot', s.current_slot, s.generation, s.slot_count, + slots.slot, slots.generation + FROM awa.claim_ring_state s CROSS JOIN awa.claim_ring_slots slots WHERE s.singleton AND slots.generation>=0 AND slots.generation<=s.generation +) +SELECT clock_timestamp() AS observed_at, current_database() AS database_name, + (SELECT oid::bigint FROM pg_database WHERE datname=current_database()) AS database_oid, + pg_backend_pid() AS observer_pid, + (SELECT backend_start FROM pg_stat_activity WHERE pid=pg_backend_pid()) AS observer_backend_start, + current_setting('application_name') AS observer_application, + rings.*, rings.slot <> rings.current_slot AS sealed, + ns.nspname AS schema_name, parent.relname AS parent_name, + child.relname AS child_name, child.oid::bigint AS child_oid, + pg_relation_filenode(child.oid)::bigint AS filenode, + pg_get_partkeydef(parent.oid) AS partition_definition, + pg_table_size(child.oid) AS table_bytes, + pg_indexes_size(child.oid) AS index_bytes, + pg_total_relation_size(child.oid) AS total_bytes, + stats.n_live_tup AS estimated_live_rows, + stats.n_dead_tup AS estimated_dead_rows, stats.last_analyze, stats.last_autoanalyze +FROM rings +JOIN pg_namespace ns ON ns.nspname='awa' +JOIN pg_class parent ON parent.relnamespace=ns.oid AND parent.relkind='p' + AND pg_get_partkeydef(parent.oid)=format('LIST (%I)', rings.partition_key) +JOIN pg_inherits inheritance ON inheritance.inhparent=parent.oid +JOIN pg_class child ON child.oid=inheritance.inhrelid AND child.relkind='r' + AND child.relnamespace=ns.oid AND child.relname=parent.relname || '_' || rings.slot::text +LEFT JOIN pg_stat_all_tables stats ON stats.relid=child.oid +ORDER BY rings.family, rings.slot, parent.relname; diff --git a/scripts/lock-pressure/check_parsers.py b/scripts/lock-pressure/check_parsers.py new file mode 100644 index 000000000..46bba3aa8 --- /dev/null +++ b/scripts/lock-pressure/check_parsers.py @@ -0,0 +1,68 @@ +"""Pure synthetic replay, provenance and negative controls; no database required.""" +import gzip +import importlib.util +import json +from pathlib import Path +import tempfile + +HERE = Path(__file__).resolve().parent + + +def load(name): + spec = importlib.util.spec_from_file_location('check_' + name, HERE / (name + '.py')) + module = importlib.util.module_from_spec(spec) + spec.loader.exec_module(module) + return module + + +def main(): + evidence, archive = (load(name) for name in ('evidence', 'archive')) + fixture = HERE / 'fixtures/synthetic.json' + rows = fixture.read_text().splitlines() + assert len(rows) == 41 + with tempfile.TemporaryDirectory() as temporary: + root = Path(temporary) + source = {'path': str(fixture), 'original_path': 'synthetic.json', 'source_key': 'synthetic:stable', 'gzip': False} + reference = root / 'reference' + reference.mkdir() + old = evidence.Utilities(reference, classify_statement=evidence.core.classify) + for row in map(json.loads, rows): + old.record(row) + old_summary = old.finish() + result = evidence.replay([source], root / 'fast') + assert all(result[key] == value for key, value in old_summary.items()) + for name in ('utility-events.jsonl', 'utility-summary.json'): + assert (reference / name).read_bytes() == (root / 'fast' / name).read_bytes() + keys = result['selected_keys'] + assert keys and evidence.compare_feed_replay(keys, keys)['match'] + assert not evidence.compare_feed_replay(keys + keys[:1], keys)['match'] + assert not evidence.compare_feed_replay([], keys)['match'] + raw = root / 'raw' + raw.mkdir() + original = raw / 'server.json' + original.write_bytes(fixture.read_bytes()) + compressed = root / 'source.json.gz' + compressed.write_bytes(gzip.compress(fixture.read_bytes())) + receipt = {'phase': 'verified_before_unlink', 'source_key': 'synthetic:stable', 'archive_path': str(compressed), 'compressed_sha256': archive.sha(compressed)[0], 'compressed_bytes': compressed.stat().st_size, 'source_sha256': archive.sha(original)[0], 'original_bytes': original.stat().st_size, 'ordinal': 0, 'original_path': str(original)} + receipts = root / 'receipts.jsonl' + receipts.write_text(json.dumps(receipt) + '\n') + stat = original.stat() + index = [{'path': str(original), 'device': stat.st_dev, 'inode': stat.st_ino, 'source_key': 'synthetic:stable'}] + assert len(archive.replay_sources(raw, root, receipts, index)) == 1 + compressed.write_bytes(b'corrupt') + try: + archive.replay_sources(raw, root, receipts, index) + except AssertionError: + pass + else: + raise AssertionError('corrupt archive accepted') + partial = root / 'partial.json' + partial.write_bytes(b'{invalid}\n{}') + invalid = evidence.replay([dict(source, path=str(partial))], root / 'invalid') + assert any(row['reason'] == 'invalid JSON' for row in invalid['invalid']) + assert any(row['reason'] == 'partial EOF' for row in invalid['invalid']) + print('41 synthetic records: replay event bytes, provenance multiplicity, archive corruption, partial/invalid JSON controls passed') + + +if __name__ == '__main__': + main() diff --git a/scripts/lock-pressure/core_parser.py b/scripts/lock-pressure/core_parser.py new file mode 100644 index 000000000..00a90d22d --- /dev/null +++ b/scripts/lock-pressure/core_parser.py @@ -0,0 +1,80 @@ +import re + +TARGETS = {'lock_ax', 'truncate'} + +def normalize_message(message): + return re.sub(r'^(?:\[[^\]\n]+:\d+\]\s*)+', '', message) + +def split_sql(sql): + if ';' not in sql: + stripped=sql.strip() + return [stripped] if stripped else [] + parts=[]; start=0; position=0; quote=None; dollar=None; block=0; line=False + while position < len(sql): + char=sql[position]; nextchar=sql[position+1:position+2] + if line: + if char=='\n':line=False + elif block: + if char=='/' and nextchar=='*':block+=1;position+=1 + elif char=='*' and nextchar=='/':block-=1;position+=1 + elif dollar: + if sql.startswith(dollar,position):position+=len(dollar)-1;dollar=None + elif quote: + if char==quote: + if nextchar==quote:position+=1 + else:quote=None + elif char=='\\' and quote=="'":position+=1 + elif char=='-' and nextchar=='-':line=True;position+=1 + elif char=='/' and nextchar=='*':block=1;position+=1 + elif char in "'\"":quote=char + elif char=='$': + match=re.match(r'\$(?:[A-Za-z_]\w*)?\$',sql[position:]) + if match:dollar=match.group();position+=len(dollar)-1 + elif char==';': + if sql[start:position].strip():parts.append(sql[start:position].strip()) + start=position+1 + position+=1 + if sql[start:].strip():parts.append(sql[start:].strip()) + return parts + +def remove_leading_comments(sql): + while True: + sql=sql.lstrip() + if sql.startswith('--'): + end=sql.find('\n');sql='' if end<0 else sql[end+1:] + elif sql.startswith('/*'): + depth=1;index=2 + while index256:raise RuntimeError('raw file count cap') + for p in sorted(paths): + if not p.is_file() or p.suffix not in ('.json','.internal','.log'):continue + st=p.stat();base=f'{st.st_dev}:{st.st_ino}';key=base + active=[k for k,v in self.streams.items() if v['device']==st.st_dev and v['inode']==st.st_ino and v['path']==str(p) and not v.get('archived')] + if active:key=active[-1] + elif key in self.streams and self.streams[key].get('archived'):key=base+':generation'+str(self.next_ordinal) + if key not in self.streams: + self.streams[key]={'source_key':key,'original_path':str(p),'path':str(p),'device':st.st_dev,'inode':st.st_ino,'ordinal':self.next_ordinal,'offset':0,'partial':b''};self.next_ordinal+=1 + def poll(self,budget=32*1024**2): + with self.lock:return self._poll(budget) + def _poll(self,budget): + self.discover();used=0;began=time.monotonic() + for stream in list(self.streams.values()): + if stream.get('archived') or stream.get('staged'):continue + path=pathlib.Path(stream['path']) + while usedself.line_cap:self.errors.append({'reason':'line cap','source_key':stream['source_key'],'offset':offset}) + else:self.line(stream,line,offset) + offset+=len(line)+1 + if len(stream['partial'])>self.line_cap:self.errors.append({'reason':'partial line cap','source_key':stream['source_key']});stream['partial']=b'' + self.last_poll={'bytes':used,'elapsed_s':time.monotonic()-began,'budget_bytes':budget,'soft_cpu_deadline_s':.25} + return used + def line(self,stream,line,offset): + text=line.decode(errors='replace');record=None + if pathlib.Path(stream['original_path']).suffix=='.json': + try:record=json.loads(text) + except ValueError:self.errors.append({'reason':'invalid JSON','source_key':stream['source_key'],'offset':offset}) + selected=(record and record.get('error_severity') in SEVERE) or any(x in text for x in CRASH) or (not record and re.search(r'\b(?:WARNING|ERROR|FATAL|PANIC):',text)) + if not selected:return + if any(x in text for x in ('terminated by signal','TRAP:','PANIC:','all server processes terminated')) or (record and record.get('error_severity')=='PANIC'):self.crashes.append({'source_key':stream['source_key'],'offset':offset}) + event={'source_key':stream['source_key'],'original_path':stream['original_path'],'offset':offset,'sha256':hashlib.sha256(line).hexdigest(),'rendered':record.get('error_severity','')+': '+record.get('message','') if record else text,'record':record} + data=(json.dumps(event,separators=(',',':'))+'\n').encode() + if self.bytes+len(data)>self.cap:self.errors.append({'reason':'feed cap'});raise RuntimeError('feed cap') + with self.feed.open('ab') as f:f.write(data) + self.bytes+=len(data);self.emitted.append((stream['source_key'],offset,event['sha256'])) + def drain(self): + while self.poll():pass + return self.status() + def status(self):return {'last_poll':getattr(self,'last_poll',None),'streams':[{**s,'partial':len(s['partial'])} for s in self.streams.values()],'emitted_keys':self.emitted,'feed_bytes':self.bytes,'errors':self.errors,'crashes':self.crashes} + +class Utilities: + def __init__(self,out,cap=256*1024**2,classify_statement=core.classify): + self.classify_statement=classify_statement;self.out=pathlib.Path(out);self.out.mkdir(exist_ok=True);self.events=(self.out/'utility-events.jsonl').open('w');self.sessions={};self.counts=collections.Counter();self.minutes=collections.defaultdict(collections.Counter);self.quality=collections.Counter();self.cap=cap;self.protocol=collections.Counter() + def emit(self,event): + data=json.dumps(event)+'\n' + if self.events.tell()+len(data.encode())>self.cap:raise RuntimeError('utility event cap') + self.events.write(data) + kind=event.get('kind','unknown');outcome=event.get('outcome','unknown');self.counts[kind+':'+outcome]+=1 + self.minutes[((event.get('started_at') or event.get('at') or 'unknown')[:16],event.get('app',''),event.get('database'),kind)][outcome]+=1 + def record(self,row): + sid=row.get('session_id') or 'pid:'+str(row.get('pid'));s=self.sessions.setdefault(sid,{'last':None,'pending':None});line=row.get('line_num');last=s['last'];s['last']=line + if isinstance(line,int) and isinstance(last,int): + if line<=last:self.quality['duplicate_or_out_of_order']+=1 + elif line>last+1:self.quality['line_gaps']+=1 + app=row.get('application_name','');msg=core.normalize_message(row.get('message',''));statement=None + if msg.startswith('statement: '):statement=msg[11:];protocol='simple' + else: + m=re.match(r'execute\s+(?:fetch from\s+)?[^:]+:\s*(.*)',msg,re.S) + if m:statement=m[1];protocol='extended' + if statement is not None: + if s['pending']: + self.quality['new_start_before_end']+=1 + if s['pending']['kind'] in core.TARGETS:self.emit({**s['pending'],'outcome':'unknown','reason':'new start before end'}) + s['pending']={**self.classify_statement(statement),'sql':statement,'app':app,'database':row.get('dbname'),'session_id':sid,'pid':row.get('pid'),'started_at':row.get('timestamp'),'start_line':line,'protocol':protocol};self.protocol[protocol+'_starts']+=1;return + duration=re.match(r'duration:\s*([\d.]+)\s+ms(?:\s+(parse|bind|execute)\b)?',msg,re.I) + if duration: + phase=(duration[2] or 'generic').lower();self.protocol[phase+'_durations']+=1 + if phase in ('parse','bind'): + if s['pending']:self.quality['phase_during_pending']+=1 + return + pending=s['pending'];s['pending']=None + if pending: + if pending['kind'] in core.TARGETS:self.emit({**pending,'outcome':'success','sqlstate':None,'finished_at':row.get('timestamp'),'end_line':line,'duration_ms':float(duration[1])}) + elif pending['kind']=='unknown_batch':self.emit({**pending,'outcome':'unknown','reason':'batch completion'}) + return + if row.get('error_severity') in ('ERROR','FATAL','PANIC'): + pending=s['pending'];s['pending']=None;state=row.get('state_code') + if pending and pending['kind'] in core.TARGETS:self.emit({**pending,'outcome':'blocked' if state=='55P03' else 'error','sqlstate':state,'finished_at':row.get('timestamp'),'end_line':line}) + elif pending and pending['kind']=='unknown_batch':self.emit({**pending,'outcome':'unknown','reason':'batch error','sqlstate':state}) + elif re.match(r'(LOCK|TRUNCATE)\b',core.remove_leading_comments(row.get('statement','')),re.I):self.emit({'kind':'pre_execute_error','app':app,'database':row.get('dbname'),'sqlstate':state,'outcome':'error','at':row.get('timestamp'),'sql':row.get('statement')}) + def finish(self): + for s in self.sessions.values(): + pending=s['pending'] + if pending and pending['kind'] in core.TARGETS|{'unknown_batch'}:self.emit({**pending,'outcome':'unknown','reason':'EOF'}) + self.events.close() + result={'counts':dict(self.counts),'quality':dict(self.quality),'protocol':dict(self.protocol),'per_minute_by_start':[{'minute_utc':key[0],'app':key[1],'database':key[2],'kind':key[3],'counts':dict(values)} for key,values in sorted(self.minutes.items(),key=lambda kv:str(kv[0]))],'unit':'direct SQL commands; successes do not prove transaction commit; no internal lock-request claim'} + (self.out/'utility-summary.json').write_text(json.dumps(result,indent=2)+'\n');return result + +def replay(sources,out,event_cap=256*1024**2): + out=pathlib.Path(out);out.mkdir(exist_ok=True);utility=Utilities(out,cap=event_cap);selected=[];invalid=[] + for source in sources: + opener=gzip.open if source.get('gzip') else open;offset=0 + with opener(source['path'],'rb') as f: + for raw in f: + if not raw.endswith(b'\n'):invalid.append({'source_key':source['source_key'],'offset':offset,'reason':'partial EOF'}) + line=raw.rstrip(b'\n');text=line.decode(errors='replace');row=None + if pathlib.Path(source['original_path']).suffix=='.json': + try:row=json.loads(text);utility.record(row) + except (ValueError,TypeError):invalid.append({'source_key':source['source_key'],'offset':offset,'reason':'invalid JSON'}) + if (row and row.get('error_severity') in SEVERE) or any(x in text for x in CRASH) or (not row and re.search(r'\b(?:WARNING|ERROR|FATAL|PANIC):',text)):selected.append((source['source_key'],offset,hashlib.sha256(line).hexdigest())) + offset+=len(raw) + result=utility.finish();result.update(invalid=invalid,selected_keys=selected);(out/'replay.json').write_text(json.dumps(result,indent=2)+'\n');return result + + +def compare_feed_replay(live_keys,replayed_keys): + live=[tuple(key) for key in live_keys];replayed=[tuple(key) for key in replayed_keys] + live_counts=collections.Counter(live);replayed_counts=collections.Counter(replayed) + live_streams=collections.defaultdict(list);replayed_streams=collections.defaultdict(list) + for key in live:live_streams[key[0]].append(key) + for key in replayed:replayed_streams[key[0]].append(key) + live_duplicates=sum(count-1 for count in live_counts.values() if count>1) + replay_duplicates=sum(count-1 for count in replayed_counts.values() if count>1) + multiplicity_match=live_counts==replayed_counts + stream_order_match=dict(live_streams)==dict(replayed_streams) + return {'match':multiplicity_match and stream_order_match and not live_duplicates and not replay_duplicates, + 'multiplicity_match':multiplicity_match,'per_stream_order_match':stream_order_match, + 'global_interleaving_match':live==replayed,'live_events':len(live),'replayed_events':len(replayed), + 'live_duplicate_keys':live_duplicates,'replayed_duplicate_keys':replay_duplicates, + 'missing_event_instances':sum((live_counts-replayed_counts).values()), + 'extra_event_instances':sum((replayed_counts-live_counts).values()), + 'order_scope':'exact within each inode stream; cross-stream replay order differs from live polling interleaving'} diff --git a/scripts/lock-pressure/fixtures/synthetic.json b/scripts/lock-pressure/fixtures/synthetic.json new file mode 100644 index 000000000..9e77b760a --- /dev/null +++ b/scripts/lock-pressure/fixtures/synthetic.json @@ -0,0 +1,41 @@ +{"session_id": "control", "line_num": 1, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : "} +{"session_id": "control", "line_num": 2, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : "} +{"session_id": "control", "line_num": 3, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : "} +{"session_id": "control", "line_num": 4, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : "} +{"session_id": "control", "line_num": 5, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT 1"} +{"session_id": "control", "line_num": 6, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT 1"} +{"session_id": "control", "line_num": 7, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT '$1', $2"} +{"session_id": "control", "line_num": 8, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT '$1', $2"} +{"session_id": "control", "line_num": 9, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : LOCK TABLE awa.ready_0 IN ACCESS EXCLUSIVE MODE NOWAIT"} +{"session_id": "control", "line_num": 10, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : LOCK TABLE awa.ready_0 IN ACCESS EXCLUSIVE MODE NOWAIT"} +{"session_id": "control", "line_num": 11, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : TRUNCATE awa.ready_0"} +{"session_id": "control", "line_num": 12, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : TRUNCATE awa.ready_0"} +{"session_id": "control", "line_num": 13, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : -- comment\nSELECT 1"} +{"session_id": "control", "line_num": 14, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : -- comment\nSELECT 1"} +{"session_id": "control", "line_num": 15, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : /* nested /*comment*/ end */ SELECT 1"} +{"session_id": "control", "line_num": 16, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : /* nested /*comment*/ end */ SELECT 1"} +{"session_id": "control", "line_num": 17, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT 'unterminated"} +{"session_id": "control", "line_num": 18, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT 'unterminated"} +{"session_id": "control", "line_num": 19, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT $$unterminated"} +{"session_id": "control", "line_num": 20, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT $$unterminated"} +{"session_id": "control", "line_num": 21, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT ';'"} +{"session_id": "control", "line_num": 22, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT ';'"} +{"session_id": "control", "line_num": 23, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT 1; LOCK awa.ready_0 IN ACCESS EXCLUSIVE MODE NOWAIT"} +{"session_id": "control", "line_num": 24, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT 1; LOCK awa.ready_0 IN ACCESS EXCLUSIVE MODE NOWAIT"} +{"session_id": "control", "line_num": 25, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : TRUNCATE awa.ready_0; SELECT 1"} +{"session_id": "control", "line_num": 26, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : TRUNCATE awa.ready_0; SELECT 1"} +{"session_id": "control", "line_num": 27, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : /* ; */ SELECT 1"} +{"session_id": "control", "line_num": 28, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : /* ; */ SELECT 1"} +{"session_id": "control", "line_num": 29, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT $$a;b$$"} +{"session_id": "control", "line_num": 30, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT $$a;b$$"} +{"session_id": "control", "line_num": 31, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : -- ;\nTRUNCATE awa.ready_0"} +{"session_id": "control", "line_num": 32, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : -- ;\nTRUNCATE awa.ready_0"} +{"session_id": "control", "line_num": 33, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : SELECT 1;"} +{"session_id": "control", "line_num": 34, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : SELECT 1;"} +{"session_id": "control", "line_num": 35, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : ;"} +{"session_id": "control", "line_num": 36, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : ;"} +{"session_id": "control", "line_num": 37, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : --commentonly"} +{"session_id": "control", "line_num": 38, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : --commentonly"} +{"session_id": "control", "line_num": 39, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "execute : /* unterminated comment"} +{"session_id": "control", "line_num": 40, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "LOG", "message": "duration: 0.1 ms execute : /* unterminated comment"} +{"session_id": "control", "line_num": 42, "pid": 1, "application_name": "synthetic", "dbname": "control", "timestamp": "2026-11-08T00:00:00Z", "error_severity": "WARNING", "message": "control retained warning"} diff --git a/scripts/lock-pressure/prepare_overlay.py b/scripts/lock-pressure/prepare_overlay.py new file mode 100644 index 000000000..047b0c895 --- /dev/null +++ b/scripts/lock-pressure/prepare_overlay.py @@ -0,0 +1,77 @@ +import argparse, difflib, hashlib, json, pathlib, re, subprocess + +if not __debug__: + raise RuntimeError('prune overlay verification requires Python assertions') + +PACKET=pathlib.Path(__file__).resolve().parent +FUNCTIONS={'prune_oldest':'queue','prune_oldest_leases':'lease','prune_oldest_claims':'claim','rollup_terminal_count_delta_slot':'terminal_delta'} +def sha(text):return hashlib.sha256(text.encode()).hexdigest() +def transform(original, helper): + source=original;proof=[] + for name,ring in FUNCTIONS.items(): + starts=list(re.finditer(rf'^ (?:pub )?async fn {name}\(',source,re.M)) + assert len(starts)==1,(name,'signature count') + start=starts[0].start();opening=source.index(' {\n',start)+2 + closing=re.search(r'^ }\n',source[opening:],re.M) + assert closing,(name,'closing brace') + end=opening+closing.start();body=source[opening:end] + # Source pins and function-level anchor counts make this fail closed on drift. + locks=list(re.finditer(r'sqlx::query\(&format!\(\s*"LOCK TABLE [^"\n]+"\s*\)\)\s*\.execute\(tx\.as_mut\(\)\)\s*\.await',body)) + assert len(locks)==1,(name,'LOCK expression count',len(locks)) + lock=locks[0];expression=lock.group() + generation_binding='_generation' if name in ('prune_oldest_leases','prune_oldest_claims') else 'generation' + if generation_binding=='_generation':assert re.search(r'let Some\(\(slot, _generation\)\)',body),(name,'generation binding') + modified=body[:lock.start()]+'prune_trace_lock(slot, '+generation_binding+', async { '+expression+' }).await'+body[lock.end():] + stage_replacements=[] + truncates=list(re.finditer(r'sqlx::query\(&format!\(\s*"TRUNCATE TABLE [^"\n]+"\s*\)\)\s*\.execute\(tx\.as_mut\(\)\)\s*\.await',modified)) + assert len(truncates)==1,(name,'TRUNCATE expression count',len(truncates)) + for truncate in reversed(truncates): + expression_truncate=truncate.group() + replacement='prune_trace_stage("truncate", async { '+expression_truncate+' }).await' + modified=modified[:truncate.start()]+replacement+modified[truncate.end():] + stage_replacements.append((replacement,expression_truncate)) + commit_count=modified.count('tx.commit().await') + modified=modified.replace('tx.commit().await','prune_trace_stage("commit", async { tx.commit().await }).await') + wrapped='\n prune_trace_call(pool, "'+ring+'", async {'+modified+' }).await\n' + # Removal of the two wrappers must recover every original byte of this function body. + recovered=modified.replace('prune_trace_stage("commit", async { tx.commit().await }).await','tx.commit().await') + for replacement,expression_truncate in stage_replacements:recovered=recovered.replace(replacement,expression_truncate,1) + recovered=recovered.replace('prune_trace_lock(slot, '+generation_binding+', async { '+expression+' }).await',expression,1) + assert recovered==body + source=source[:opening]+wrapped+source[end:] + proof.append({'function':name,'ring':ring,'original_body_sha256':sha(body),'original_lock_expression_sha256':sha(expression),'initial_lock_expressions':1,'truncate_expressions':len(truncates),'direct_commit_expressions':commit_count,'recovered_body_byte_identical':True}) + if 'async fn settle_prune_tx(' in source: + start=source.index('async fn settle_prune_tx(') + closing=re.search(r'^}\n',source[start:],re.M);assert closing + end=start+closing.end();body=source[start:end] + assert body.count('tx.commit().await')==1 + after=body.replace('tx.commit().await','prune_trace_stage("commit", async { tx.commit().await }).await') + assert after.replace('prune_trace_stage("commit", async { tx.commit().await }).await','tx.commit().await')==body + source=source[:start]+after+source[end:] + proof.append({'function':'settle_prune_tx','direct_commit_expressions':1,'recovered_body_byte_identical':True,'original_body_sha256':sha(body)}) + anchor='const DEFAULT_SCHEMA: &str = "awa";' + assert source.count(anchor)==1 + return source.replace(anchor,helper+'\n'+anchor,1),proof + +def main(): + parser=argparse.ArgumentParser(description='Generate source-only prune tracing overlays without changing the repository.') + parser.add_argument('--repository',type=pathlib.Path,required=True) + parser.add_argument('--variant',action='append',required=True,metavar='LABEL=REF') + parser.add_argument('--out',type=pathlib.Path,required=True) + args=parser.parse_args();versions={} + for variant in args.variant: + label,separator,ref=variant.partition('=') + if not separator or not re.fullmatch(r'[A-Za-z0-9_-]+',label) or not ref or label in versions:parser.error('variants require unique safe LABEL=REF values') + versions[label]=subprocess.check_output(['git','-C',str(args.repository),'rev-parse','--verify','--end-of-options',ref+'^{commit}'],text=True).strip() + args.out.mkdir(parents=True,exist_ok=False) + helper=(PACKET/'prune_trace.rs').read_text();manifest={'status':'SOURCE_ONLY_UNCOMPILED_UNRUN','helper_sha256':sha(helper),'versions':{}} + for label,commit in versions.items(): + original=subprocess.check_output(['git','-C',str(args.repository),'show',commit+':awa-model/src/queue_storage.rs']).decode() + after,proof=transform(original,helper) + directory=args.out/label;directory.mkdir() + (directory/'overlay.diff').write_text(''.join(difflib.unified_diff(original.splitlines(True),after.splitlines(True),fromfile='a/awa-model/src/queue_storage.rs',tofile='b/awa-model/src/queue_storage.rs'))) + manifest['versions'][label]={'commit':commit,'before_sha256':sha(original),'after_sha256':sha(after),'proof':proof} + manifest['prepare_sha256']=sha(pathlib.Path(__file__).read_text()) + (args.out/'manifest.json').write_text(json.dumps(manifest,indent=2)+'\n') + print(json.dumps(manifest,indent=2)) +if __name__=='__main__':main() diff --git a/scripts/lock-pressure/prune_calls.py b/scripts/lock-pressure/prune_calls.py new file mode 100644 index 000000000..a97287ab7 --- /dev/null +++ b/scripts/lock-pressure/prune_calls.py @@ -0,0 +1,46 @@ +"""Bounded post-close derived trace ledger; missing pairs remain incomplete.""" +import collections,datetime,json,pathlib +MARKER='AWA_PRUNE_CALL ' +def analyze(out,cap=64*1024**2): + out=pathlib.Path(out);calls={};malformed=[];read=0 + paths=[out/'run.log']+sorted(out.glob('*.stderr'))+sorted(out.glob('*.stdout')) + for path in paths: + if not path.exists():continue + with path.open()as stream: + for number,line in enumerate(stream,1): + read+=len(line.encode()) + if read>cap:raise RuntimeError('prune trace analysis input bound; raw retained') + offset=line.find(MARKER) + if offset<0:continue + try:row=json.loads(line[offset+len(MARKER):]) + except ValueError: + malformed.append({'path':str(path),'line':number});continue + key=(row['client_pid'],row['call_id']);item=calls.setdefault(key,{'client_pid':row['client_pid'],'call_id':row['call_id'],'ring':row['ring'],'application':row['application'],'events':[]}) + item['events'].append({'source':str(path),'line':number,**row}) + minutes=collections.Counter();incomplete=[] + for item in calls.values(): + starts=[e for e in item['events']if e['event']=='call_start'];ends=[e for e in item['events']if e['event']=='call_end'] + item['complete']=len(starts)==len(ends)==1 + if not item['complete']:incomplete.append({'client_pid':item['client_pid'],'call_id':item['call_id'],'start_count':len(starts),'end_count':len(ends)});continue + end=ends[0];detail=end['details'];item['elapsed_ns']=detail['elapsed_ns'];item['classification']=detail['classification'];item['result_debug']=detail['result_debug'] + minute=datetime.datetime.fromtimestamp(starts[0]['utc_ns']/1e9,datetime.timezone.utc).strftime('%Y-%m-%dT%H:%M:00Z') + item['start_minute_utc']=minute + minutes[(minute,item['ring'],item['application'],detail['classification'])]+=1 + item['initial_lock_events']=[e for e in item['events']if e['event']=='initial_lock_end'] + item['stage_events']=[e for e in item['events']if e['event']=='stage_end'] + item['initial_55P03']=any(e['details'].get('sqlstate')=='55P03'for e in item['initial_lock_events']) + item['truncate_successes']=sum(e['details']['stage']=='truncate'and e['details']['ok']for e in item['stage_events']) + item['commit_successes']=sum(e['details']['stage']=='commit'and e['details']['ok']for e in item['stage_events']) + result={'schema':'prune-call-ledger-v1','calls':list(calls.values()),'per_start_minute':[{'minute':k[0],'ring':k[1],'application':k[2],'classification':k[3],'count':v}for k,v in sorted(minutes.items())],'incomplete_calls':incomplete,'malformed_marker_lines':malformed,'capture_scope':'run.log and top-level stderr/stdout; child forwarding must be proven by controls','limits':['Client pid/call id is process scoped, not a backend identity.','Unlogged/cancelled/panicked calls are unknown; logging errors were intentionally ignored by overlay.','Initial LOCK55P03 distinguished; later Blocked/error is not assigned an exact SQLSTATE unless an observed stage/server ledger supplies it.','Successful TRUNCATE is not commit proof; stages are attached to the same invocation.','UTC minute boundaries are observations; request duration uses monotonic elapsed.']} + (out/'prune-call-ledger.json').write_text(json.dumps(result,indent=2)+'\n');return {'calls':len(calls),'complete':len(calls)-len(incomplete),'incomplete':len(incomplete),'malformed':len(malformed)} + +def main(): + import argparse + parser=argparse.ArgumentParser(description=__doc__) + parser.add_argument('directory',type=pathlib.Path) + parser.add_argument('--cap-bytes',type=int,default=64*1024**2) + args=parser.parse_args() + if args.cap_bytes<=0:parser.error('--cap-bytes must be positive') + print(json.dumps(analyze(args.directory,args.cap_bytes),indent=2)) + +if __name__=='__main__':main() diff --git a/scripts/lock-pressure/prune_trace.rs b/scripts/lock-pressure/prune_trace.rs new file mode 100644 index 000000000..2c2d2da45 --- /dev/null +++ b/scripts/lock-pressure/prune_trace.rs @@ -0,0 +1,134 @@ +#[derive(Default)] +struct PruneCallTrace { + call_id: String, + ring: &'static str, + application: String, + lock_ok: std::sync::atomic::AtomicU64, + lock_failed: std::sync::atomic::AtomicU64, +} +static PRUNE_CALL_SEQUENCE: std::sync::atomic::AtomicU64 = std::sync::atomic::AtomicU64::new(1); +tokio::task_local! { + static PRUNE_CALL_TRACE: std::sync::Arc; +} +fn prune_trace_utc_ns() -> u64 { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .unwrap_or_default().as_nanos() as u64 +} +fn prune_trace_emit(context: &PruneCallTrace, event: &str, details: serde_json::Value) { + use std::io::Write; + let row = serde_json::json!({ + "event": event, "call_id": context.call_id, "ring": context.ring, + "application": context.application, "client_pid": std::process::id(), + "utc_ns": prune_trace_utc_ns(), "details": details + }); + let _ = writeln!(std::io::stderr().lock(), "AWA_PRUNE_CALL {}", row); +} +trait PruneTraceOutcome { + fn trace_status(&self) -> &'static str; +} +impl PruneTraceOutcome for PruneOutcome { + fn trace_status(&self) -> &'static str { + match self { + Self::Blocked { .. } => "blocked", + Self::Pruned { .. } => "pruned", + Self::Noop => "noop", + Self::SkippedActive { .. } => "skipped", + } + } +} +impl PruneTraceOutcome for TerminalDeltaSlotRollup { + fn trace_status(&self) -> &'static str { + match self { + Self::Blocked => "blocked", + Self::Rolled { .. } => "pruned", + Self::Empty => "noop", + Self::SkippedActive | Self::SkippedMvccPinned => "skipped", + } + } +} +async fn prune_trace_call( + pool: &PgPool, + ring: &'static str, + future: impl std::future::Future>, +) -> Result { + let context = std::sync::Arc::new(PruneCallTrace { + call_id: format!("{}:{}", std::process::id(), PRUNE_CALL_SEQUENCE.fetch_add(1, Ordering::Relaxed)), + ring, + application: pool.connect_options().get_application_name().unwrap_or("").to_owned(), + ..Default::default() + }); + let started = std::time::Instant::now(); + prune_trace_emit(&context, "call_start", serde_json::json!({})); + let result = PRUNE_CALL_TRACE.scope(context.clone(), future).await; + let debug = format!("{:?}", result); + let ok = context.lock_ok.load(Ordering::Relaxed); + let failed = context.lock_failed.load(Ordering::Relaxed); + let status = result.as_ref().map(|value| value.trace_status()).unwrap_or("error"); + let blocked_or_error = matches!(status, "blocked" | "error"); + let classification = if failed > 0 { + "initial_lock_failed" + } else if ok > 0 && blocked_or_error { + "lock_succeeded_then_BlockedorError" + } else if blocked_or_error { + "pre_lock_other" + } else if status == "pruned" { + "pruned" + } else { + status + }; + prune_trace_emit(&context, "call_end", serde_json::json!({ + "elapsed_ns": started.elapsed().as_nanos() as u64, + "classification": classification, "result_debug": debug, + "initial_lock_successes": ok, "initial_lock_failures": failed + })); + result +} +async fn prune_trace_lock( + slot: i32, + generation: i64, + future: impl std::future::Future>, +) -> Result { + let context = PRUNE_CALL_TRACE.try_with(std::sync::Arc::clone).ok(); + let started = std::time::Instant::now(); + if let Some(context) = &context { + prune_trace_emit(context, "initial_lock_start", serde_json::json!({"slot": slot, "generation": generation})); + } + let result = future.await; + if let Some(context) = &context { + let (status, code, error) = match &result { + Ok(_) => { context.lock_ok.fetch_add(1, Ordering::Relaxed); ("ok", None, None) } + Err(error) => { + context.lock_failed.fetch_add(1, Ordering::Relaxed); + ("error", error.as_database_error().and_then(|e| e.code()).map(|v| v.into_owned()), Some(format!("{:?}", error))) + } + }; + prune_trace_emit(context, "initial_lock_end", serde_json::json!({ + "slot": slot, "generation": generation, "status": status, + "sqlstate": code, "error_debug": error, + "elapsed_ns": started.elapsed().as_nanos() as u64 + })); + } + result +} + +async fn prune_trace_stage( + stage: &'static str, + future: impl std::future::Future>, +) -> Result { + let context = PRUNE_CALL_TRACE.try_with(std::sync::Arc::clone).ok(); + let started = std::time::Instant::now(); + if let Some(context) = &context { + prune_trace_emit(context, "stage_start", serde_json::json!({"stage": stage})); + } + let result = future.await; + if let Some(context) = &context { + prune_trace_emit(context, "stage_end", serde_json::json!({ + "stage": stage, "ok": result.is_ok(), + "sqlstate": result.as_ref().err().and_then(|e| e.as_database_error()).and_then(|e| e.code()).map(|v| v.into_owned()), + "error_debug": result.as_ref().err().map(|e| format!("{:?}", e)), + "elapsed_ns": started.elapsed().as_nanos() as u64 + })); + } + result +} diff --git a/scripts/lock-pressure/relation-lock-snapshot.sql b/scripts/lock-pressure/relation-lock-snapshot.sql new file mode 100644 index 000000000..68bf32a01 --- /dev/null +++ b/scripts/lock-pressure/relation-lock-snapshot.sql @@ -0,0 +1,45 @@ +WITH targets AS MATERIALIZED ( + SELECT pid, backend_start::text, datid, datname, application_name, state, + query_start::text, xact_start::text, wait_event_type, wait_event, + query_id, left(query,4096) AS query_text + FROM pg_stat_activity + WHERE application_name = ANY($1::text[]) + AND backend_type = 'client backend' + AND datname LIKE 'awa_footprint_%' + AND pid <> pg_backend_pid() +), locks AS MATERIALIZED ( + SELECT locks.pid, locks.database, locks.relation, locks.mode, + locks.granted, locks.fastpath + FROM pg_locks AS locks + JOIN targets ON targets.pid = locks.pid + WHERE locks.locktype = 'relation' +), counts AS ( + SELECT pid, + count(*) FILTER (WHERE granted) AS granted_rows, + count(*) FILTER (WHERE granted AND fastpath) AS fastpath_rows, + count(*) FILTER (WHERE granted AND NOT fastpath) AS nonfastpath_rows, + count(*) FILTER (WHERE NOT granted) AS waiting_rows, + count(*) FILTER (WHERE granted AND NOT fastpath AND mode IN + ('AccessShareLock', 'RowShareLock', 'RowExclusiveLock')) AS nonfastpath_weak_rows, + count(DISTINCT (database, relation)) FILTER (WHERE granted) AS distinct_relations + FROM locks GROUP BY pid +), modes AS ( + SELECT pid, jsonb_agg(to_jsonb(grouped) - 'pid') AS mode_counts + FROM ( + SELECT pid, mode, granted, fastpath, count(*) AS rows + FROM locks GROUP BY pid, mode, granted, fastpath + ) AS grouped GROUP BY pid +) +SELECT clock_timestamp()::text AS server_observed_at, + COALESCE(jsonb_agg(to_jsonb(targets) || jsonb_build_object( + 'granted_rows', COALESCE(counts.granted_rows, 0), + 'fastpath_rows', COALESCE(counts.fastpath_rows, 0), + 'nonfastpath_rows', COALESCE(counts.nonfastpath_rows, 0), + 'waiting_rows', COALESCE(counts.waiting_rows, 0), + 'nonfastpath_weak_rows', COALESCE(counts.nonfastpath_weak_rows, 0), + 'distinct_relations', COALESCE(counts.distinct_relations, 0), + 'mode_counts', COALESCE(modes.mode_counts, '[]'::jsonb) + )) FILTER (WHERE targets.pid IS NOT NULL), '[]'::jsonb) AS backends +FROM targets +LEFT JOIN counts USING (pid) +LEFT JOIN modes USING (pid) diff --git a/scripts/lock-pressure/replay.py b/scripts/lock-pressure/replay.py new file mode 100644 index 000000000..711fe55e3 --- /dev/null +++ b/scripts/lock-pressure/replay.py @@ -0,0 +1,39 @@ +"""Replay a caller-supplied list of closed PostgreSQL log sources.""" +import argparse +import importlib.util +import json +from pathlib import Path + +if not __debug__: + raise RuntimeError('lock-pressure evidence verification requires Python assertions') + +HERE = Path(__file__).resolve().parent + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('--sources', type=Path, required=True) + parser.add_argument('--out', type=Path, required=True) + parser.add_argument('--event-cap-bytes', type=int, default=256*1024**2) + args = parser.parse_args() + if args.event_cap_bytes <= 0: + parser.error('--event-cap-bytes must be positive') + sources = json.loads(args.sources.read_text()) + if not isinstance(sources, list): + parser.error('--sources must contain a JSON list') + for source in sources: + for key in ('path', 'original_path', 'source_key'): + if not isinstance(source.get(key), str): + parser.error('each source requires string ' + key) + path = Path(source['path']) + source['path'] = str(path if path.is_absolute() else args.sources.resolve().parent / path) + args.out.mkdir(parents=True, exist_ok=False) + spec = importlib.util.spec_from_file_location('log_evidence', HERE / 'evidence.py') + evidence = importlib.util.module_from_spec(spec) + spec.loader.exec_module(evidence) + result = evidence.replay(sources, args.out, args.event_cap_bytes) + print(json.dumps({'counts': result['counts'], 'invalid_lines': len(result['invalid'])}, indent=2)) + + +if __name__ == '__main__': + main() diff --git a/scripts/lock-pressure/slot_observer.py b/scripts/lock-pressure/slot_observer.py new file mode 100644 index 000000000..f9a5eb991 --- /dev/null +++ b/scripts/lock-pressure/slot_observer.py @@ -0,0 +1,83 @@ +"""Packet-only serialized psycopg hook; no hard client/network deadline.""" +from pathlib import Path +import time + +CATALOG = (Path(__file__).parent / 'catalog.sql').read_text() +RINGS = {'queue': 'queue', 'lease': 'lease', 'claim': 'claim'} +MEMBERS = {'lease_claim_batches': 'claimed_count', + 'lease_claim_closure_batches': 'closed_count', + 'ready_claim_attempt_batches': 'claimed_count', + 'receipt_completion_batches': 'completed_count'} + + +def quote(identifier): + return '"' + identifier.replace('"', '""') + '"' + + +def fetch(connection, sql, parameters=()): + with connection.cursor() as cursor: + cursor.execute(sql, parameters) if parameters else cursor.execute(sql) + names = [column.name for column in cursor.description] + return [dict(zip(names, row)) if not isinstance(row, dict) else row + for row in cursor.fetchall()] + + +def observe(connection, phase, *, exact_rows=False, budget_seconds=2.0): + """Use an idle autocommit connection exclusively until this call settles. + + Caller schedules metadata every 60s and exact counts at checkpoints. A 100ms + server timeout bounds statements, not client/network wall time. Transport + failures propagate: caller must close/reset rather than reuse the connection. + """ + if not connection.autocommit or connection.info.transaction_status.name != 'IDLE': + raise ValueError('observer requires an idle autocommit connection') + start = time.monotonic() + output = {'phase': phase, 'client_start_ns': time.time_ns(), + 'status': 'unknown', 'slots': [], 'exact_rows_requested': exact_rows, + 'server_statement_timeout_ms': 100, 'server_lock_timeout_ms': 100, + 'admission_budget_seconds': budget_seconds, + 'hard_client_deadline': False} + original = fetch(connection, "SELECT current_setting('statement_timeout') AS statement_timeout, current_setting('lock_timeout') AS lock_timeout")[0] + transport_failed = False + try: + fetch(connection, "SELECT set_config('statement_timeout','100ms',false), set_config('lock_timeout','100ms',false)") + rows = fetch(connection, CATALOG) + for slot in rows: + slot['row_count_status'] = 'not_requested' + output['slots'].append(slot) + if not exact_rows or not slot['sealed']: + continue + if time.monotonic()-start >= budget_seconds: + slot['row_count_status'] = 'budget_exhausted' + continue + family = RINGS[slot['family']] + table = quote(slot['schema_name']) + '.' + quote(slot['child_name']) + column = MEMBERS.get(slot['parent_name']) + member = 'coalesce(sum(' + quote(column) + '),0)::bigint' if column else 'NULL::bigint' + query = f'''SELECT clock_timestamp() AS counted_at, count(*)::bigint AS physical_rows, + {member} AS counted_members, + (SELECT generation FROM awa.{family}_ring_slots WHERE slot=%s) AS slot_generation, + (SELECT current_slot FROM awa.{family}_ring_state WHERE singleton) AS current_slot, + pg_relation_filenode(%s::oid)::bigint AS filenode FROM ONLY {table}''' + try: + counted = fetch(connection, query, (slot['slot'], slot['child_oid']))[0] + slot.update(count=counted, member_column=column, + row_count_status=('counted' if counted['slot_generation'] == slot['slot_generation'] + and counted['current_slot'] != slot['slot'] and counted['filenode'] == slot['filenode'] + else 'stale_generation_or_rewrite')) + except Exception as error: + if not getattr(error, 'sqlstate', None): + raise + slot.update(row_count_status='unknown', error=type(error).__name__, sqlstate=error.sqlstate) + output['status'] = 'observed_metadata' + except Exception as error: + if not getattr(error, 'sqlstate', None): + transport_failed = True + raise + output.update(error=type(error).__name__, sqlstate=error.sqlstate) + finally: + if not transport_failed: + fetch(connection, "SELECT set_config('statement_timeout',%s,false), set_config('lock_timeout',%s,false)", + (original['statement_timeout'], original['lock_timeout'])) + output.update(client_end_ns=time.time_ns(), elapsed_seconds=time.monotonic()-start) + return output