Files
buzz/crates/buzz-admin/tests/postgres_cold_start.rs
Luke Tornquist c6340a45a0 fix(deletion): give the scheduled drain the cold-start DB connector (#8146)
## Summary

The scheduled `buzz-admin deletions drain` Job never gets past its first
database connection in a hosted staging deployment. Every run exits 5
after exactly 3 seconds with `pool timed out while waiting for an open
connection`.

The drain starts in a fresh pod with no mesh sidecar, and that pod's
first connection can take longer than the relay's 3-second acquisition
budget. `connect_store()` in `buzz-deletion` inherits that budget from
`DbConfig::default()`, with no retry. In the same pod, the same command
run 15 seconds later succeeds. TCP to Postgres, Redis, and S3 from a
sidecar-less pod is fine.

#7770 fixed the same failure for `buzz-admin storage-snapshot`, but only
inside `buzz-admin`. This PR moves that connector into `buzz-db` as
`Db::connect_cold_start` and uses it from both run-once workers:

- **Pool settings:** a 30s acquisition budget, and no idle spare
connections (`min_connections: 0`).
- **Retries:** startup timeouts and transient transport errors retry at
most twice, after 2s and 5s, so startup waits at most 97s.
- **No retry:** configuration, authentication, TLS, and protocol errors
fail immediately, and the error message stays free of credentials.
- **Per-worker settings:** each worker keeps its own pool size.
Storage-snapshot stays at 1 connection, and deletion stays at
`BUZZ_DB_POOL_SIZE` (default 20). Each worker also keeps its session
timeouts.
- **Startup events:** the stderr events carry a worker prefix.
Storage-snapshot still emits `storage_snapshot_db_connect_*`, and the
deletion worker now emits `deletion_db_connect_*`.

- **Error text:** the exhaustion message is now `{worker} database
startup failed after …`. For storage-snapshot that reads
`storage_snapshot database startup failed …` instead of `storage
snapshot database startup failed …`. Nothing in this repo matches on
that string.
- **Session-setup failures:** SQLx retries a failed `after_connect` hook
(writer floor guard, session timeouts, isolation assertion) until the
acquire deadline. Those failures therefore surface as `timeout`, are
retried, and fail closed after at most 97s instead of immediately.

Relay pool defaults are unchanged. The deletion CLI's operator commands
(`list`, `approve`, …) use the same connector. They normally run inside
the warm relay container, where the first attempt succeeds.

**What got simpler:** there is now one cold-start connector instead of a
`buzz-admin`-private copy that the deletion worker couldn't reach.
`storage_snapshot_startup.rs` is gone, and its unit tests moved with the
code. The two Postgres startup tests now share one harness with the
drain's tests (`postgres_storage_snapshot.rs` →
`postgres_cold_start.rs`).

### Related issue

Follow-up to #7770 (same failure, other worker) and #7827 (the drain
CronJob). No duplicate found.

### Testing

All at head `1545de7b5`:

- **GitHub CI:** green on attempt 1, including `PostgreSQL Domain /
PostgreSQL Tests`.
- **Blox:**
- fmt, `clippy --workspace --all-targets -D warnings`, and the `buzz-db`
/ `buzz-admin` / `buzz-deletion` tests pass.
- All four `postgres_cold_start` tests pass, each against a freshly
migrated database.
- Falsification: with main's `connect_store` restored, the drain retry
test fails.
- **Agent review:** two rounds. All findings are fixed or disclosed; the
error-text change is listed above.
- **Agent exercise:** real `buzz-admin deletions list` / `deletions
drain` against local Postgres 17 behind a fault proxy.
  - **5s delay:** succeeds on attempt 1 (3/3). Main fails at about 3.5s.
- **Dropped handshake, then 5s delay:** attempt 1 fails with
`UnexpectedEof`, then a 2s backoff, then attempt 2 succeeds (3/3).
- **Wrong password, missing database or malformed URL:** exit 5 after
one attempt.
- **Persistent rejection:** exit 5 after three attempts, with 2s and 5s
backoffs.
  - The deletion queue stayed empty throughout.
- **Not covered:** an approved deletion, real S3 / Pod Identity, TLS and
session-setup failures, and a live 97s stall.

---------

Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>
Co-authored-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>
2026-10-08 10:30:38 -04:00

374 lines
14 KiB
Rust

//! Run the real run-once workers through delayed/broken PostgreSQL connections.
//! The PostgreSQL nextest wrapper supplies a separate database per test.
use std::process::{ExitStatus, Stdio};
use std::sync::atomic::{AtomicUsize, Ordering};
use std::sync::Arc;
use std::time::Duration;
use serde_json::{json, Value};
use sqlx::postgres::PgPoolOptions;
use sqlx::PgPool;
use tokio::io::{AsyncRead, AsyncReadExt, AsyncWriteExt};
use tokio::net::{TcpListener, TcpStream};
use tokio::process::Command;
use tokio::task::{JoinHandle, JoinSet};
use tokio::time::{sleep, timeout};
use url::Url;
struct Server {
address: std::net::SocketAddr,
requests: Arc<AtomicUsize>,
task: JoinHandle<()>,
}
impl Drop for Server {
fn drop(&mut self) {
self.task.abort();
}
}
async fn postgres_proxy(database_url: &str, reject: usize, delay: Duration) -> Server {
let target = Url::parse(database_url).expect("test database URL");
let target = (
target.host_str().expect("database host").to_owned(),
target.port().unwrap_or(5432),
);
let listener = TcpListener::bind("127.0.0.1:0").await.expect("proxy");
let address = listener.local_addr().expect("proxy address");
let requests = Arc::new(AtomicUsize::new(0));
let connections = Arc::clone(&requests);
let task = tokio::spawn(async move {
let mut sessions = JoinSet::new();
loop {
tokio::select! {
accepted = listener.accept() => {
let (mut client, _) = accepted.expect("accept database connection");
let index = connections.fetch_add(1, Ordering::SeqCst);
let target = target.clone();
sessions.spawn(async move {
if index < reject {
// Wait for the client handshake before dropping the
// connection, so this is an I/O failure, not a refused
// connection SQLx would retry inside the same attempt.
let mut header = [0; 4];
let _ = client.read_exact(&mut header).await;
return;
}
sleep(delay).await;
let mut upstream = TcpStream::connect(target).await.expect("real Postgres");
let _ = tokio::io::copy_bidirectional(&mut client, &mut upstream).await;
});
}
result = sessions.join_next(), if !sessions.is_empty() => {
result.expect("session").expect("proxy session completed");
}
}
}
});
Server {
address,
requests,
task,
}
}
async fn s3_listing() -> Server {
let listener = TcpListener::bind("127.0.0.1:0").await.expect("S3 listener");
let address = listener.local_addr().expect("S3 address");
let requests = Arc::new(AtomicUsize::new(0));
let observed = Arc::clone(&requests);
let task = tokio::spawn(async move {
let sha = "a".repeat(64);
let contents: String = [
(format!("{sha}.bin"), 100),
(format!("{sha}.thumb.jpg"), 10),
(
format!("_meta/00000000-0000-0000-0000-000000000001/{sha}.json"),
30,
),
]
.into_iter()
.map(|(key, size)| {
format!(
"<Contents><Key>{key}</Key><Size>{size}</Size>\
<LastModified>2026-09-20T00:00:00.000Z</LastModified>\
<ETag>\"test\"</ETag><StorageClass>STANDARD</StorageClass></Contents>"
)
})
.collect();
let body = format!(
"<ListBucketResult xmlns=\"http://s3.amazonaws.com/doc/2006-03-01/\">\
<Name>test-bucket</Name><Prefix></Prefix><MaxKeys>1000</MaxKeys>\
<IsTruncated>false</IsTruncated>{contents}\
</ListBucketResult>"
);
loop {
let (mut stream, _) = listener.accept().await.expect("S3 connection");
observed.fetch_add(1, Ordering::SeqCst);
let mut request = Vec::new();
let mut chunk = [0; 1024];
while !request.windows(4).any(|bytes| bytes == b"\r\n\r\n") {
let read = stream.read(&mut chunk).await.expect("S3 request");
assert!(read > 0 && request.len() + read <= 16 * 1024);
request.extend_from_slice(&chunk[..read]);
}
assert!(String::from_utf8_lossy(&request).contains("list-type=2"));
let response = format!(
"HTTP/1.1 200 OK\r\nContent-Type: application/xml\r\nContent-Length: {}\r\nConnection: close\r\n\r\n{body}",
body.len()
);
stream
.write_all(response.as_bytes())
.await
.expect("S3 response");
}
});
Server {
address,
requests,
task,
}
}
async fn database() -> (String, PgPool) {
let url = std::env::var("BUZZ_TEST_DATABASE_URL")
.expect("run through scripts/postgres-test-run.sh for an isolated database");
let pool = PgPoolOptions::new()
.max_connections(1)
.connect(&url)
.await
.expect("test DB");
sqlx::query(
"INSERT INTO storage_accounting_snapshots \
(singleton, snapshot, completed_at, duration_ms, max_objects, code_sha) \
VALUES (TRUE, $1, NOW(), 1, 100, 'before')",
)
.bind(json!({"previous": "complete"}))
.execute(&pool)
.await
.expect("seed last-good snapshot");
(url, pool)
}
async fn capture(reader: impl AsyncRead + Unpin) -> std::io::Result<String> {
let mut bytes = Vec::new();
reader.take(64 * 1024).read_to_end(&mut bytes).await?;
Ok(String::from_utf8_lossy(&bytes).into_owned())
}
struct WorkerOutput {
status: ExitStatus,
stdout: String,
stderr: String,
}
async fn run_worker(database_url: &str, proxy: &Server, s3: &Server) -> WorkerOutput {
run_admin(
database_url,
proxy,
&["storage-snapshot", "--max-objects", "100"],
&[
("BUZZ_S3_ENDPOINT", format!("http://{}", s3.address)),
("BUZZ_STORAGE_SNAPSHOT_CODE_SHA", "startup-test".to_owned()),
],
)
.await
}
/// Run the scheduled deletion drain against an idle queue. Its Redis pool is
/// lazy and an idle drain never reaches S3, so neither endpoint needs to exist.
async fn run_drain(database_url: &str, proxy: &Server) -> WorkerOutput {
run_admin(
database_url,
proxy,
&["deletions", "drain", "--executor-id", "cold-start-test"],
&[
("BUZZ_S3_ENDPOINT", "http://127.0.0.1:9".to_owned()),
("REDIS_URL", "redis://127.0.0.1:9".to_owned()),
],
)
.await
}
async fn run_admin(
database_url: &str,
proxy: &Server,
args: &[&str],
env: &[(&str, String)],
) -> WorkerOutput {
let mut url = Url::parse(database_url).expect("database URL");
url.set_host(Some("127.0.0.1")).expect("proxy host");
url.set_port(Some(proxy.address.port()))
.expect("proxy port");
// The proxy deliberately interrupts the PostgreSQL handshake. Keep TLS
// out of this local transport test so it exercises sqlx::Error::Io.
url.query_pairs_mut().append_pair("sslmode", "disable");
// nextest relocates executables when extracting a test archive. Keep the
// compile-time Cargo path only as the fallback for local cargo test runs.
let worker_binary = std::env::var_os("NEXTEST_BIN_EXE_buzz_admin")
.unwrap_or_else(|| env!("CARGO_BIN_EXE_buzz-admin").into());
let mut child = Command::new(worker_binary)
.args(args)
.env_clear()
.env("DATABASE_URL", url.as_str())
.env("BUZZ_S3_BUCKET", "test-bucket")
.env("BUZZ_S3_REGION", "us-east-1")
.env("BUZZ_S3_ACCESS_KEY", "test-access-key")
.env("BUZZ_S3_SECRET_KEY", "test-secret-key")
.envs(env.iter().map(|(key, value)| (key, value)))
.stdout(Stdio::piped())
.stderr(Stdio::piped())
.kill_on_drop(true)
.spawn()
.expect("start real worker");
let stdout = child.stdout.take().expect("stdout");
let stderr = child.stderr.take().expect("stderr");
let completed = timeout(Duration::from_secs(25), async {
tokio::try_join!(child.wait(), capture(stdout), capture(stderr))
})
.await;
let (status, stdout, stderr) = match completed {
Ok(output) => output.expect("worker output"),
Err(_) => {
child.kill().await.expect("kill hung worker");
panic!("worker did not finish within 25 seconds");
}
};
WorkerOutput {
status,
stdout,
stderr,
}
}
fn events(output: &str) -> Vec<Value> {
output
.lines()
.filter_map(|line| serde_json::from_str(line).ok())
.collect()
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn storage_snapshot_retries_then_connects_after_the_old_three_second_budget() {
let (url, pool) = database().await;
let proxy = postgres_proxy(&url, 1, Duration::from_secs(5)).await;
let s3 = s3_listing().await;
let output = run_worker(&url, &proxy, &s3).await;
assert!(
output.status.success(),
"{}\n{}",
output.stdout,
output.stderr
);
assert_eq!(
proxy.requests.load(Ordering::SeqCst),
2,
"one rejected connection, one lock-owning session, no spare pool connections"
);
assert_eq!(s3.requests.load(Ordering::SeqCst), 1);
let startup = events(&output.stderr);
assert!(startup.iter().any(
|event| event["event"] == "storage_snapshot_db_connect_failed"
&& event["attempt"] == 1
&& event["retry_in_ms"] == 2000
));
assert!(startup.iter().any(
|event| event["event"] == "storage_snapshot_db_connect_completed"
&& event["attempt"] == 2
&& event["attempt_elapsed_ms"].as_u64().unwrap() >= 5000
));
let scan = events(&output.stdout);
assert_eq!(scan.first().unwrap()["event"], "storage_snapshot_started");
assert_eq!(scan.last().unwrap()["event"], "storage_snapshot_completed");
let (snapshot, revision): (Value, String) = sqlx::query_as(
"SELECT snapshot, code_sha FROM storage_accounting_snapshots WHERE singleton = TRUE",
)
.fetch_one(&pool)
.await
.expect("saved snapshot");
assert_eq!(revision, "startup-test");
assert_eq!(snapshot["physical_objects"], 3);
assert_eq!(snapshot["physical_bytes"], 140);
assert_eq!(snapshot["logical_bytes"], 110);
assert_eq!(snapshot["logical_objects"], 1);
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn storage_snapshot_exhaustion_never_lists_s3_or_replaces_the_last_good_snapshot() {
let (url, pool) = database().await;
let proxy = postgres_proxy(&url, usize::MAX, Duration::ZERO).await;
let s3 = s3_listing().await;
let output = run_worker(&url, &proxy, &s3).await;
assert_eq!(output.status.code(), Some(5), "{}", output.stderr);
assert_eq!(proxy.requests.load(Ordering::SeqCst), 3);
assert_eq!(s3.requests.load(Ordering::SeqCst), 0);
assert!(!output.stdout.contains("storage_snapshot_started"));
assert!(!output.stdout.contains("storage_snapshot_completed"));
let failures: Vec<_> = events(&output.stderr)
.into_iter()
.filter(|event| event["event"] == "storage_snapshot_db_connect_failed")
.collect();
assert_eq!(failures.len(), 3);
assert!(failures.last().unwrap()["retry_in_ms"].is_null());
let (snapshot, revision): (Value, String) = sqlx::query_as(
"SELECT snapshot, code_sha FROM storage_accounting_snapshots WHERE singleton = TRUE",
)
.fetch_one(&pool)
.await
.expect("last good snapshot");
assert_eq!(snapshot, json!({"previous": "complete"}));
assert_eq!(revision, "before");
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn deletion_drain_retries_then_connects_after_the_old_three_second_budget() {
let (url, _pool) = database().await;
let proxy = postgres_proxy(&url, 1, Duration::from_secs(5)).await;
let output = run_drain(&url, &proxy).await;
assert!(
output.status.success(),
"{}\n{}",
output.stdout,
output.stderr
);
// The rejected dial plus the successful retry. The drain's first claim
// can race SQLx's asynchronous release of the startup connection and dial
// one more session, so the count is a lower bound; the startup events
// below are what pin the retry.
assert!(proxy.requests.load(Ordering::SeqCst) >= 2);
let startup = events(&output.stderr);
assert!(startup
.iter()
.any(|event| event["event"] == "deletion_db_connect_failed"
&& event["attempt"] == 1
&& event["retry_in_ms"] == 2000));
assert!(startup
.iter()
.any(|event| event["event"] == "deletion_db_connect_completed"
&& event["attempt"] == 2
&& event["attempt_elapsed_ms"].as_u64().unwrap() >= 5000));
}
#[tokio::test]
#[ignore = "requires Postgres"]
async fn deletion_drain_exhaustion_fails_after_three_bounded_attempts() {
let (url, _pool) = database().await;
let proxy = postgres_proxy(&url, usize::MAX, Duration::ZERO).await;
let output = run_drain(&url, &proxy).await;
assert_eq!(output.status.code(), Some(5), "{}", output.stderr);
assert_eq!(proxy.requests.load(Ordering::SeqCst), 3);
let failures: Vec<_> = events(&output.stderr)
.into_iter()
.filter(|event| event["event"] == "deletion_db_connect_failed")
.collect();
assert_eq!(failures.len(), 3);
assert!(failures.last().unwrap()["retry_in_ms"].is_null());
assert!(output
.stderr
.contains("deletion database startup failed after 3 attempt(s)"));
}