mirror of
https://github.com/block/buzz.git
synced 2026-10-28 04:51:40 +00:00
## Summary
Relay pods on large deployments can take over 5 minutes to open their
health port, and right now nothing shows which startup step is slow.
Startup timing ends at `metrics_bind`, and the slow work all happens
after it.
This PR times every startup step from Postgres connect through public
listener bind. It does not change startup behavior.
- Each step logs `Startup phase started` and `Startup phase finished`,
with `phase`, `elapsed_ms`, and `status` (`succeeded` / `degraded` /
`failed`, the same values `buzz_process_lifecycle` records use).
- Gauge `buzz_startup_phase_current{phase}` is `1` while a step runs and
`0` after it ends. A pod that is still starting shows exactly which step
it is on.
- Gauge `buzz_startup_phase_seconds{phase}` records each finished step's
duration.
- The startup NIP-43 membership reconcile logs `NIP-43 startup
reconciliation progress` every 5,000 communities, with `done`, `total`,
`republished`, `failed`, and `elapsed_ms`.
These are gauges rather than counters on purpose. Each value is written
once per boot, and a monotonic-counter scrape drops a series' first
sample, so a one-shot counter never shows up.
## Contract change
`deploy/charts/buzz/README.md` ("Early-startup telemetry contract") said
the early lifecycle phases are log-only. That still holds: `crypto_init`
through `metrics_bind` are unchanged and emit no metrics.
The README now also documents the post-bind steps. The guard in
`boot_lifecycle.rs` now allows exactly the two `buzz_startup_phase_*`
families. It still rejects any other startup, boot, or lifecycle family,
and it also rejects any exported label value that names an early phase.
## Design
- `crates/buzz-relay/src/startup_steps.rs` adds a closed `StartupStep`
vocabulary (18 steps) and a `StepTimer` guard.
- A step ends exactly once:
- `finish()` → `succeeded`
- `degrade()` then `finish()` → `degraded` (a non-fatal error branch)
- dropped without finishing → `failed` (covers `?` early returns and
panics)
- The NIP-43 and large-roster reconciles now return `ReconcileSummary {
repaired, failed }`. A sweep where any item fails ends its step
`degraded`, and the final log line includes the `failed` count. NIP-FI
warm ends `degraded` when any issuer did not warm. The deprecated
`reconcile_nip43_membership_snapshots` wrapper still returns `repaired`.
- Steps that are disabled by config (migrate, audit connect, NIP-FI
warm, git probe, NIP-43 reconcile) are not timed, so their series never
appear.
- The gauges are set once, so they age out after the existing gauge idle
timeout (2700 s with default intervals; logged as `idle_timeout_secs`).
A step that runs longer than that loses its `_current` series. The
README says so.
- Progress logging runs only for the `Bootstrap` reconcile. The 60 s
maintenance sweep stays quiet.
## What got simpler
Little got simpler in the code: this mostly adds instrumentation. One CI
gap closed along the way: the 54 `config` tests and the 9 non-ignored
`boot_lifecycle` tests, which ran in no CI lane, now run in `test-unit`.
The instrumentation is scoped as small as I could make it, and it is the
evidence needed for the follow-up that should delete code: moving the
per-community NIP-43 reconcile off the pre-bind path, after which the
900 s startup-probe override can go back to the chart default.
## Testing
- `startup_steps` unit tests (`DebuggingRecorder`):
- a running step is current and has no duration
- a finished step clears current and records its elapsed time
- dropped and degraded steps clear current and record a duration
- log capture: `finish`, `degrade`+`finish`, drop, and panic each emit
exactly one `Startup phase finished` record with the right `status`.
Mutating `degrade()` to a no-op and removing the ends-once guard makes
these tests fail.
- the vocabulary is unique and shares no names with the early lifecycle
phases
- Tests that capture logs or check callsite interest now share
`test_support::tracing_dispatch_lock()`. These are the `startup_steps`
helpers, two `telemetry` tests, and the `config` and `bridge`
log-capture helpers. tracing-core caches each callsite's interest across
the whole process. Without the lock, the new panic test lost its record
in 60 of 150 parallel runs of `telemetry:: startup_steps:: config::`.
With the lock it failed 0 of 300. Removing the lock from `gauges()`
brings the failures back (53 of 100 runs).
- `nip43_progress_logs_every_interval_inside_the_startup_sweep_only`
checks the cadence at 79,942 communities (15 progress lines, none at the
start or end) and table-tests that the maintenance sweep never logs
progress.
-
`boot_lifecycle::successful_main_emits_complete_lifecycle_and_reports_current_startup_step`
boots the real relay binary against a TCP peer that never speaks
Postgres. It asserts that `/metrics` shows
`buzz_startup_phase_current{phase="db_connect"} 1` and no finished-step
durations, and that no early phase leaks into metrics.
- **CI routing.** `just test-unit` picks relay tests by hand-maintained
filter. Before this PR, CI's filters selected none of the
`startup_steps`, `telemetry`, `config` or non-ignored `boot_lifecycle`
tests above; the NIP-43 cadence test is picked up by the existing
`handlers::side_effects::tests::` clause. Its infra-free relay stanza
now selects `startup_steps::tests::`, `telemetry::tests::` and
`config::tests::` (anchored so `nip_fi_config` is not selected twice),
and a new `cargo nextest run -p buzz-relay --test boot_lifecycle` line
runs the non-ignored `boot_lifecycle` tests (they spawn the real binary
and need no Postgres or Redis; the Postgres cases stay `#[ignore]`d).
`scripts/run-tests.sh` mirrors both, running `telemetry` and `config`
single-threaded because they mutate process env.
### Manual check
1. `just relay` (or run `buzz-relay` against local Postgres and Redis).
2. Once the relay is up: `curl -s localhost:9102/metrics | grep
buzz_startup_phase`. Every step that ran has a `_seconds` value, and
every `_current` value is 0.
3. In the relay logs, `"Startup phase finished"` lines show each step's
`elapsed_ms`.
---------
Signed-off-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>
Co-authored-by: Elrond <28d6302a099e5225b02c4155ac4236e4912603df2ab08dbfc2f4fef08ce598c8@buzz.block.builderlab.xyz>
872 lines
34 KiB
Rust
872 lines
34 KiB
Rust
use std::{
|
|
collections::BTreeMap,
|
|
io::{Read as _, Write as _},
|
|
net::{TcpListener, TcpStream},
|
|
process::{Child, Command, ExitStatus, Output, Stdio},
|
|
sync::mpsc,
|
|
thread::{self, JoinHandle},
|
|
time::{Duration, Instant},
|
|
};
|
|
|
|
use serde_json::Value;
|
|
|
|
use buzz_relay::lifecycle::StartupPhase;
|
|
use buzz_relay::startup_steps;
|
|
use buzz_relay::state::REDIS_BOOTSTRAP_FAILURE;
|
|
|
|
const VALID_RELAY_PRIVATE_KEY: &str =
|
|
"0000000000000000000000000000000000000000000000000000000000000001";
|
|
const CHILD_TIMEOUT: Duration = Duration::from_secs(10);
|
|
const MAX_CAPTURE_BYTES: u64 = 1024 * 1024;
|
|
/// Bound on every wait for the relay to export a metric family.
|
|
const METRICS_SCRAPE_DEADLINE: Duration = Duration::from_secs(8);
|
|
|
|
struct RelayProcess {
|
|
child: Option<Child>,
|
|
stdout: Option<JoinHandle<CapturedStream>>,
|
|
stderr: Option<JoinHandle<CapturedStream>>,
|
|
scratch_dir: std::path::PathBuf,
|
|
}
|
|
|
|
struct CapturedStream {
|
|
retained: Vec<u8>,
|
|
total_bytes: u64,
|
|
}
|
|
|
|
impl RelayProcess {
|
|
fn spawn(environment: &[(&str, &str)]) -> Self {
|
|
let scratch_dir =
|
|
std::env::temp_dir().join(format!("buzz-boot-lifecycle-{}", uuid::Uuid::new_v4()));
|
|
let mut command = Command::new(env!("CARGO_BIN_EXE_buzz-relay"));
|
|
command
|
|
.env_clear()
|
|
.env("RUST_BACKTRACE", "0")
|
|
.env("RUST_LOG", "buzz_relay=info")
|
|
.env("BUZZ_GIT_REPO_PATH", scratch_dir.join("repos"))
|
|
.env("BUZZ_GIT_PACK_CACHE_PATH", scratch_dir.join("pack-cache"))
|
|
.stdout(Stdio::piped())
|
|
.stderr(Stdio::piped());
|
|
for (name, value) in environment {
|
|
command.env(name, value);
|
|
}
|
|
let mut child = command.spawn().expect("spawn buzz-relay child process");
|
|
let stdout = child.stdout.take().expect("relay stdout pipe");
|
|
let stderr = child.stderr.take().expect("relay stderr pipe");
|
|
Self {
|
|
child: Some(child),
|
|
stdout: Some(thread::spawn(move || capture_stream(stdout))),
|
|
stderr: Some(thread::spawn(move || capture_stream(stderr))),
|
|
scratch_dir,
|
|
}
|
|
}
|
|
|
|
fn try_wait(&mut self) -> Option<ExitStatus> {
|
|
self.child
|
|
.as_mut()
|
|
.expect("relay child")
|
|
.try_wait()
|
|
.expect("poll relay child")
|
|
}
|
|
|
|
fn wait(mut self, timeout: Duration) -> Output {
|
|
let deadline = Instant::now() + timeout;
|
|
let status = loop {
|
|
if let Some(status) = self.try_wait() {
|
|
break status;
|
|
}
|
|
if Instant::now() >= deadline {
|
|
let child = self.child.as_mut().expect("relay child");
|
|
let _ = child.kill();
|
|
let _ = child.wait();
|
|
panic!("buzz-relay child exceeded {timeout:?}");
|
|
}
|
|
thread::sleep(Duration::from_millis(10));
|
|
};
|
|
self.child.take();
|
|
let output = Output {
|
|
status,
|
|
stdout: join_capture(self.stdout.take(), "stdout"),
|
|
stderr: join_capture(self.stderr.take(), "stderr"),
|
|
};
|
|
let _ = std::fs::remove_dir_all(&self.scratch_dir);
|
|
output
|
|
}
|
|
|
|
fn terminate(mut self) -> Output {
|
|
self.child
|
|
.as_mut()
|
|
.expect("relay child")
|
|
.kill()
|
|
.expect("terminate exact relay child");
|
|
self.wait(Duration::from_secs(2))
|
|
}
|
|
}
|
|
|
|
impl Drop for RelayProcess {
|
|
fn drop(&mut self) {
|
|
if let Some(child) = self.child.as_mut() {
|
|
let _ = child.kill();
|
|
let _ = child.wait();
|
|
}
|
|
let _ = std::fs::remove_dir_all(&self.scratch_dir);
|
|
}
|
|
}
|
|
|
|
fn capture_stream(mut stream: impl std::io::Read) -> CapturedStream {
|
|
let mut retained = Vec::new();
|
|
let mut total_bytes = 0_u64;
|
|
let mut chunk = [0_u8; 8192];
|
|
loop {
|
|
let read = stream.read(&mut chunk).expect("read relay output pipe");
|
|
if read == 0 {
|
|
break;
|
|
}
|
|
total_bytes = total_bytes.saturating_add(u64::try_from(read).expect("read size fits u64"));
|
|
let remaining = usize::try_from(MAX_CAPTURE_BYTES)
|
|
.expect("capture ceiling fits usize")
|
|
.saturating_sub(retained.len());
|
|
retained.extend_from_slice(&chunk[..read.min(remaining)]);
|
|
}
|
|
CapturedStream {
|
|
retained,
|
|
total_bytes,
|
|
}
|
|
}
|
|
|
|
fn join_capture(capture: Option<JoinHandle<CapturedStream>>, stream: &str) -> Vec<u8> {
|
|
let capture = capture
|
|
.expect("relay capture thread")
|
|
.join()
|
|
.expect("relay capture thread must not panic");
|
|
assert!(
|
|
capture.total_bytes <= MAX_CAPTURE_BYTES,
|
|
"relay {stream} exceeded {MAX_CAPTURE_BYTES} bytes: {}",
|
|
capture.total_bytes,
|
|
);
|
|
capture.retained
|
|
}
|
|
|
|
fn run_relay(environment: &[(&str, &str)]) -> Output {
|
|
RelayProcess::spawn(environment).wait(CHILD_TIMEOUT)
|
|
}
|
|
|
|
fn scrape_metrics(port: u16) -> std::io::Result<String> {
|
|
let address = std::net::SocketAddr::from(([127, 0, 0, 1], port));
|
|
let mut stream = TcpStream::connect_timeout(&address, Duration::from_millis(100))?;
|
|
stream.set_read_timeout(Some(Duration::from_millis(500)))?;
|
|
stream.write_all(b"GET /metrics HTTP/1.0\r\nHost: 127.0.0.1\r\n\r\n")?;
|
|
let mut response = String::new();
|
|
stream.read_to_string(&mut response)?;
|
|
Ok(response)
|
|
}
|
|
|
|
fn wait_for_relay_metrics(process: &mut RelayProcess, port: u16) -> String {
|
|
wait_for_scraped_metric(process, port, "buzz_audit_enabled")
|
|
}
|
|
|
|
/// Polls the relay's own `/metrics` until `needle` appears, bounded by
|
|
/// [`METRICS_SCRAPE_DEADLINE`]. A relay that exits first is a failure, not a
|
|
/// timeout, so the panic names the real cause.
|
|
fn wait_for_scraped_metric(process: &mut RelayProcess, port: u16, needle: &str) -> String {
|
|
let deadline = Instant::now() + METRICS_SCRAPE_DEADLINE;
|
|
loop {
|
|
assert!(
|
|
process.try_wait().is_none(),
|
|
"relay exited before exporting {needle}"
|
|
);
|
|
if let Ok(response) = scrape_metrics(port) {
|
|
if response.contains(needle) {
|
|
return response;
|
|
}
|
|
}
|
|
assert!(
|
|
Instant::now() < deadline,
|
|
"relay did not export {needle} within {METRICS_SCRAPE_DEADLINE:?}"
|
|
);
|
|
thread::sleep(Duration::from_millis(20));
|
|
}
|
|
}
|
|
|
|
/// The early lifecycle phases (crypto through metrics bind) are log-only.
|
|
/// The only startup metric families are the post-metrics-bind step gauges,
|
|
/// and no metric family or label value may name an early phase.
|
|
fn assert_no_early_lifecycle_metrics(scrape: &str) {
|
|
let step_families = [startup_steps::CURRENT_METRIC, startup_steps::SECONDS_METRIC];
|
|
for line in scrape.lines() {
|
|
for phase in StartupPhase::ALL {
|
|
assert!(
|
|
!line.contains(&format!("\"{}\"", phase.as_str())),
|
|
"logs-only lifecycle contract exported early phase {}: {line}",
|
|
phase.as_str()
|
|
);
|
|
}
|
|
let Some(name) = line
|
|
.strip_prefix("# HELP ")
|
|
.or_else(|| line.strip_prefix("# TYPE "))
|
|
.and_then(|rest| rest.split_ascii_whitespace().next())
|
|
else {
|
|
continue;
|
|
};
|
|
if step_families.contains(&name) {
|
|
continue;
|
|
}
|
|
assert!(
|
|
!["startup", "boot", "lifecycle"]
|
|
.iter()
|
|
.any(|term| name.contains(term))
|
|
&& !StartupPhase::ALL
|
|
.iter()
|
|
.any(|phase| name.contains(phase.as_str())),
|
|
"logs-only lifecycle contract emitted metric family {name}"
|
|
);
|
|
}
|
|
}
|
|
|
|
fn assert_auth_metrics_have_stable_boot_zeros(scrape: &str) {
|
|
const OUTCOMES: [&str; 11] = [
|
|
"success",
|
|
"invalid",
|
|
"banned",
|
|
"ban_check_error",
|
|
"allowlist_check_error",
|
|
"allowlist_denied",
|
|
"relay_membership_check_error",
|
|
"not_relay_member",
|
|
"timeout",
|
|
"disconnect",
|
|
"shutdown",
|
|
];
|
|
|
|
assert!(scrape.contains("# TYPE buzz_auth_attempts_total counter"));
|
|
assert!(scrape.contains("buzz_auth_attempts_total{method=\"nip42\"} 0"));
|
|
assert!(scrape.contains("# TYPE buzz_auth_outcomes_total counter"));
|
|
assert!(scrape.contains("# TYPE buzz_auth_duration_seconds histogram"));
|
|
assert!(scrape.contains("# TYPE buzz_auth_post_terminal_frames_total counter"));
|
|
assert!(scrape.contains("buzz_auth_post_terminal_frames_total{state=\"authenticated\"} 0"));
|
|
assert!(scrape.contains("buzz_auth_post_terminal_frames_total{state=\"failed\"} 0"));
|
|
assert!(scrape.contains("buzz_ws_authenticated_connections_active 0"));
|
|
|
|
for outcome in OUTCOMES {
|
|
assert!(scrape.contains(&format!(
|
|
"buzz_auth_outcomes_total{{method=\"nip42\",outcome=\"{outcome}\"}} 0"
|
|
)));
|
|
assert!(scrape.contains(&format!(
|
|
"buzz_auth_duration_seconds_count{{method=\"nip42\",outcome=\"{outcome}\"}} 0"
|
|
)));
|
|
assert!(scrape.contains(&format!(
|
|
"buzz_auth_duration_seconds_sum{{method=\"nip42\",outcome=\"{outcome}\"}} 0"
|
|
)));
|
|
assert!(scrape.lines().any(|line| {
|
|
line.starts_with("buzz_auth_duration_seconds_bucket{")
|
|
&& line.contains("le=\"+Inf\"")
|
|
&& line.contains("method=\"nip42\"")
|
|
&& line.contains(&format!("outcome=\"{outcome}\""))
|
|
&& line.ends_with(" 0")
|
|
}));
|
|
}
|
|
}
|
|
|
|
fn lifecycle_events(output: &Output) -> Vec<Value> {
|
|
let mut events: Vec<Value> = output
|
|
.stdout
|
|
.split(|byte| *byte == b'\n')
|
|
.chain(output.stderr.split(|byte| *byte == b'\n'))
|
|
.filter_map(|line| serde_json::from_slice::<Value>(line).ok())
|
|
.filter(|event| event["event_name"] == "buzz_process_lifecycle")
|
|
.collect();
|
|
events.sort_by_key(|event| event["sequence"].as_u64());
|
|
events
|
|
}
|
|
|
|
fn lifecycle_events_from(bytes: &[u8]) -> Vec<Value> {
|
|
bytes
|
|
.split(|byte| *byte == b'\n')
|
|
.filter_map(|line| serde_json::from_slice::<Value>(line).ok())
|
|
.filter(|event| event["event_name"] == "buzz_process_lifecycle")
|
|
.collect()
|
|
}
|
|
|
|
fn assert_accounting(events: &[Value]) {
|
|
assert!(!events.is_empty(), "child emitted no lifecycle events");
|
|
let boot_id = events[0]["process_boot_id"]
|
|
.as_str()
|
|
.expect("process_boot_id");
|
|
let mut counts = BTreeMap::<String, (usize, usize)>::new();
|
|
for (index, event) in events.iter().enumerate() {
|
|
assert_eq!(event["schema_version"], 1);
|
|
assert_eq!(event["sequence"], u64::try_from(index + 1).unwrap());
|
|
assert_eq!(event["process_boot_id"], boot_id);
|
|
assert_eq!(event["track"], "startup");
|
|
let count = counts
|
|
.entry(event["phase"].as_str().expect("phase").to_owned())
|
|
.or_default();
|
|
match event["edge"].as_str() {
|
|
Some("started") => count.0 += 1,
|
|
Some("terminal") => count.1 += 1,
|
|
other => panic!("unexpected lifecycle edge: {other:?}"),
|
|
}
|
|
}
|
|
assert!(
|
|
counts
|
|
.values()
|
|
.all(|(started, terminal)| *started == 1 && *terminal == 1),
|
|
"every started phase must have one terminal: {counts:?}"
|
|
);
|
|
}
|
|
|
|
fn assert_terminal(events: &[Value], phase: &str, status: &str, reason: Option<&str>) {
|
|
let terminal = events
|
|
.iter()
|
|
.find(|event| event["phase"] == phase && event["edge"] == "terminal")
|
|
.unwrap_or_else(|| panic!("missing {phase} terminal"));
|
|
assert_eq!(terminal["status"], status);
|
|
match reason {
|
|
Some(reason) => assert_eq!(terminal["reason"], reason),
|
|
None => assert!(terminal["reason"].is_null()),
|
|
}
|
|
}
|
|
|
|
fn phases(events: &[Value]) -> Vec<&str> {
|
|
events
|
|
.iter()
|
|
.filter(|event| event["edge"] == "started")
|
|
.map(|event| event["phase"].as_str().expect("phase"))
|
|
.collect()
|
|
}
|
|
|
|
#[test]
|
|
fn invalid_config_terminalizes_at_main_even_with_logs_disabled() {
|
|
let output = run_relay(&[
|
|
("RUST_LOG", "off"),
|
|
("BUZZ_BIND_ADDR", "not-a-socket-address"),
|
|
]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_eq!(
|
|
phases(&events),
|
|
[
|
|
"process_telemetry",
|
|
"crypto_init",
|
|
"tracing_init",
|
|
"config_load"
|
|
]
|
|
);
|
|
assert_terminal(&events, "config_load", "failed", Some("config_invalid"));
|
|
assert_terminal(
|
|
&events,
|
|
"process_telemetry",
|
|
"failed",
|
|
Some("config_invalid"),
|
|
);
|
|
assert_eq!(lifecycle_events_from(&output.stderr), events);
|
|
assert!(lifecycle_events_from(&output.stdout).is_empty());
|
|
}
|
|
|
|
#[test]
|
|
#[cfg(unix)]
|
|
fn config_filesystem_failure_has_a_bounded_terminal() {
|
|
let output = run_relay(&[
|
|
("RUST_LOG", "off"),
|
|
("BUZZ_GIT_REPO_PATH", "/dev/null/not-a-directory"),
|
|
]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "config_load", "failed", Some("config_invalid"));
|
|
assert_terminal(
|
|
&events,
|
|
"process_telemetry",
|
|
"failed",
|
|
Some("config_invalid"),
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn invalid_config_value_has_the_same_bounded_terminal() {
|
|
let output = run_relay(&[("RUST_LOG", "off"), ("BUZZ_DRAIN_JITTER_MS", "bogus")]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "config_load", "failed", Some("config_invalid"));
|
|
assert_terminal(
|
|
&events,
|
|
"process_telemetry",
|
|
"failed",
|
|
Some("config_invalid"),
|
|
);
|
|
}
|
|
|
|
#[test]
|
|
fn configured_otlp_terminalizes_tracing_before_a_later_failure() {
|
|
let output = run_relay(&[
|
|
("RUST_LOG", "off"),
|
|
("OTEL_EXPORTER_OTLP_ENDPOINT", "http://127.0.0.1:4317"),
|
|
("BUZZ_BIND_ADDR", "not-a-socket-address"),
|
|
]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "tracing_init", "succeeded", None);
|
|
assert_terminal(&events, "config_load", "failed", Some("config_invalid"));
|
|
}
|
|
|
|
#[test]
|
|
fn missing_key_stops_before_metrics_bind() {
|
|
let output = run_relay(&[]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_eq!(
|
|
phases(&events),
|
|
[
|
|
"process_telemetry",
|
|
"crypto_init",
|
|
"tracing_init",
|
|
"config_load",
|
|
"key_load"
|
|
]
|
|
);
|
|
assert_terminal(&events, "key_load", "failed", Some("missing"));
|
|
assert_terminal(&events, "process_telemetry", "failed", Some("missing"));
|
|
}
|
|
|
|
#[test]
|
|
fn invalid_key_uses_a_bounded_reason_without_leaking_the_value() {
|
|
let secret = "private-key-material-that-must-not-appear";
|
|
let output = run_relay(&[("BUZZ_RELAY_PRIVATE_KEY", secret)]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "key_load", "failed", Some("required_invalid"));
|
|
let combined = [output.stdout, output.stderr].concat();
|
|
assert!(!String::from_utf8_lossy(&combined).contains(secret));
|
|
}
|
|
|
|
#[test]
|
|
fn occupied_metrics_port_has_a_typed_bind_terminal() {
|
|
let occupied = TcpListener::bind(("0.0.0.0", 0)).expect("bind occupied port");
|
|
let port = occupied.local_addr().expect("occupied address").port();
|
|
let port = port.to_string();
|
|
let output = run_relay(&[
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &port),
|
|
]);
|
|
assert!(!output.status.success());
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "metrics_bind", "failed", Some("bind"));
|
|
assert_terminal(&events, "process_telemetry", "failed", Some("bind"));
|
|
}
|
|
|
|
#[test]
|
|
fn otlp_build_failure_is_degraded_without_leaking_endpoint_credentials() {
|
|
let secret = "telemetry-secret-marker";
|
|
let endpoint = format!("https://telemetry-user:{secret}@[");
|
|
let fake_database = TcpListener::bind(("127.0.0.1", 0)).expect("bind fake database");
|
|
let database_url = format!(
|
|
"postgres://buzz@127.0.0.1:{}/buzz",
|
|
fake_database.local_addr().expect("database address").port()
|
|
);
|
|
let reserved = TcpListener::bind(("127.0.0.1", 0)).expect("reserve metrics port");
|
|
let port = reserved.local_addr().expect("metrics address").port();
|
|
drop(reserved);
|
|
let port_value = port.to_string();
|
|
let mut process = RelayProcess::spawn(&[
|
|
("OTEL_EXPORTER_OTLP_ENDPOINT", &endpoint),
|
|
("RUST_LOG", "buzz_relay=warn"),
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &port_value),
|
|
("DATABASE_URL", &database_url),
|
|
]);
|
|
let scrape = wait_for_relay_metrics(&mut process, port);
|
|
assert_no_early_lifecycle_metrics(&scrape);
|
|
let output = process.terminate();
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "tracing_init", "degraded", Some("exporter_build"));
|
|
assert_terminal(
|
|
&events,
|
|
"process_telemetry",
|
|
"degraded",
|
|
Some("exporter_build"),
|
|
);
|
|
let combined = [output.stdout, output.stderr].concat();
|
|
assert!(!String::from_utf8_lossy(&combined).contains(secret));
|
|
}
|
|
|
|
#[test]
|
|
fn successful_main_emits_complete_lifecycle_and_reports_current_startup_step() {
|
|
let fake_database = TcpListener::bind(("127.0.0.1", 0)).expect("bind fake database");
|
|
let database_url = format!(
|
|
"postgres://buzz@127.0.0.1:{}/buzz",
|
|
fake_database.local_addr().expect("database address").port()
|
|
);
|
|
let reserved = TcpListener::bind(("127.0.0.1", 0)).expect("reserve metrics port");
|
|
let port = reserved.local_addr().expect("metrics address").port();
|
|
drop(reserved);
|
|
let port_value = port.to_string();
|
|
let mut process = RelayProcess::spawn(&[
|
|
("RUST_LOG", "off"),
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &port_value),
|
|
("DATABASE_URL", &database_url),
|
|
]);
|
|
let scrape = wait_for_relay_metrics(&mut process, port);
|
|
assert_no_early_lifecycle_metrics(&scrape);
|
|
assert_auth_metrics_have_stable_boot_zeros(&scrape);
|
|
// The fake database accepts TCP but never speaks Postgres, so the relay
|
|
// stays in its first post-metrics-bind step and must say so on /metrics.
|
|
let current = format!(
|
|
"{}{{phase=\"db_connect\"}} 1",
|
|
startup_steps::CURRENT_METRIC
|
|
);
|
|
let scrape = wait_for_scraped_metric(&mut process, port, ¤t);
|
|
assert!(
|
|
!scrape.contains(&format!("{}{{", startup_steps::SECONDS_METRIC)),
|
|
"no step has finished while the relay waits on Postgres"
|
|
);
|
|
assert_no_early_lifecycle_metrics(&scrape);
|
|
|
|
let output = process.terminate();
|
|
let events = lifecycle_events(&output);
|
|
assert_accounting(&events);
|
|
assert_terminal(&events, "crypto_init", "succeeded", None);
|
|
assert_terminal(&events, "tracing_init", "succeeded", None);
|
|
assert_terminal(&events, "config_load", "succeeded", None);
|
|
assert_terminal(&events, "key_load", "succeeded", None);
|
|
assert_terminal(&events, "metrics_bind", "succeeded", None);
|
|
assert_terminal(&events, "process_telemetry", "succeeded", None);
|
|
}
|
|
|
|
/// Boot gates that need a live Postgres to reach the code under test. Named
|
|
/// `postgres_tests` so `.config/nextest.toml`'s `postgres-ci` default filter
|
|
/// discovers them structurally; the wrapper hands each test its own database
|
|
/// through `DATABASE_URL`.
|
|
mod postgres_tests {
|
|
use super::*;
|
|
|
|
const REDIS_BOOTSTRAP_BUDGET: Duration = Duration::from_secs(5);
|
|
const REDIS_BOOTSTRAP_SCHEDULING_SLACK: Duration = Duration::from_secs(3);
|
|
|
|
/// A TCP peer that completes Redis's metadata handshake, then reads and
|
|
/// holds PING without replying. This distinguishes a bounded checkout +
|
|
/// PING from a refused connection, which returns before the bootstrap
|
|
/// timeout is exercised.
|
|
struct HangingRedisPeer {
|
|
redis_url: String,
|
|
request_received: mpsc::Receiver<Vec<u8>>,
|
|
stop: mpsc::Sender<()>,
|
|
worker: Option<JoinHandle<()>>,
|
|
}
|
|
|
|
impl HangingRedisPeer {
|
|
fn spawn() -> Self {
|
|
let listener = TcpListener::bind(("127.0.0.1", 0)).expect("bind fake Redis peer");
|
|
listener
|
|
.set_nonblocking(true)
|
|
.expect("set fake Redis listener nonblocking");
|
|
let port = listener.local_addr().expect("fake Redis address").port();
|
|
let (request_tx, request_received) = mpsc::channel();
|
|
let (stop, stop_rx) = mpsc::channel();
|
|
let worker = thread::spawn(move || loop {
|
|
if stop_rx.try_recv().is_ok() {
|
|
return;
|
|
}
|
|
let (mut stream, _) = match listener.accept() {
|
|
Ok(accepted) => accepted,
|
|
Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => {
|
|
thread::sleep(Duration::from_millis(10));
|
|
continue;
|
|
}
|
|
Err(error) => panic!("accept fake Redis connection: {error}"),
|
|
};
|
|
stream
|
|
.set_read_timeout(Some(Duration::from_millis(100)))
|
|
.expect("bound fake Redis read");
|
|
let mut request = Vec::new();
|
|
loop {
|
|
let mut chunk = [0_u8; 4096];
|
|
match stream.read(&mut chunk) {
|
|
Ok(0) => return,
|
|
Ok(read) => {
|
|
request.extend_from_slice(&chunk[..read]);
|
|
assert!(
|
|
request.len() <= 4096,
|
|
"fake Redis peer received an oversized request"
|
|
);
|
|
let setinfo_commands = request
|
|
.windows(b"SETINFO".len())
|
|
.filter(|window| *window == b"SETINFO")
|
|
.count();
|
|
if setinfo_commands >= 2 {
|
|
// redis-rs pipelines CLIENT SETINFO lib-name
|
|
// and lib-ver while establishing a connection.
|
|
// Complete that handshake so the relay reaches
|
|
// its explicit bootstrap PING, then hold it.
|
|
stream
|
|
.write_all(b"+OK\r\n+OK\r\n")
|
|
.expect("reply to Redis client handshake");
|
|
request.clear();
|
|
continue;
|
|
}
|
|
if request
|
|
.windows(b"PING".len())
|
|
.any(|window| window == b"PING")
|
|
{
|
|
let _ = request_tx.send(request);
|
|
let _ = stop_rx.recv_timeout(CHILD_TIMEOUT);
|
|
return;
|
|
}
|
|
}
|
|
Err(error)
|
|
if matches!(
|
|
error.kind(),
|
|
std::io::ErrorKind::WouldBlock | std::io::ErrorKind::TimedOut
|
|
) =>
|
|
{
|
|
if stop_rx.try_recv().is_ok() {
|
|
return;
|
|
}
|
|
}
|
|
Err(error) => panic!("read fake Redis request: {error}"),
|
|
}
|
|
}
|
|
});
|
|
Self {
|
|
redis_url: format!("redis://127.0.0.1:{port}"),
|
|
request_received,
|
|
stop,
|
|
worker: Some(worker),
|
|
}
|
|
}
|
|
|
|
fn redis_url(&self) -> &str {
|
|
&self.redis_url
|
|
}
|
|
|
|
fn assert_request_received(&self, logs: &str) {
|
|
let request = self
|
|
.request_received
|
|
.recv_timeout(Duration::from_secs(1))
|
|
.unwrap_or_else(|_| panic!("relay must reach the fake Redis peer: {logs}"));
|
|
assert!(!request.is_empty(), "fake Redis peer read an empty request");
|
|
}
|
|
}
|
|
|
|
impl Drop for HangingRedisPeer {
|
|
fn drop(&mut self) {
|
|
let _ = self.stop.send(());
|
|
if let Some(worker) = self.worker.take() {
|
|
worker.join().expect("fake Redis peer must not panic");
|
|
}
|
|
}
|
|
}
|
|
|
|
fn reserve_closed_port() -> u16 {
|
|
let reserved = TcpListener::bind(("127.0.0.1", 0)).expect("reserve port");
|
|
let port = reserved.local_addr().expect("reserved address").port();
|
|
drop(reserved);
|
|
port
|
|
}
|
|
|
|
/// Runs the relay until it exits on its own, or kills it once `timeout`
|
|
/// passes. Unlike `run_relay`, a relay that keeps serving is a result to
|
|
/// assert on rather than a panic, which is the whole point here.
|
|
fn run_until_exit(environment: &[(&str, &str)], timeout: Duration) -> (bool, Output) {
|
|
let mut process = RelayProcess::spawn(environment);
|
|
let deadline = Instant::now() + timeout;
|
|
while Instant::now() < deadline {
|
|
if process.try_wait().is_some() {
|
|
return (true, process.wait(Duration::from_secs(2)));
|
|
}
|
|
thread::sleep(Duration::from_millis(20));
|
|
}
|
|
(false, process.terminate())
|
|
}
|
|
|
|
/// Redis is required for pub/sub fan-out, presence, and typing, but nothing
|
|
/// in boot ever opened a command connection: `deadpool_redis` pools dial
|
|
/// lazily and `PubSubManager::new` only allocates channels, so "Redis
|
|
/// pub/sub connected" was logged against a dead port. A relay could
|
|
/// therefore boot with Redis unreachable, bind its health listener, and —
|
|
/// now that readiness answers from local lifecycle alone — advertise ready
|
|
/// for the rest of its life. The bootstrap gate is the one-time proof that
|
|
/// the command path has connected at least once, and it has to land before
|
|
/// the listener binds, because binding is the one-way latch that makes this
|
|
/// pod routable.
|
|
///
|
|
/// The git conformance probe is disabled so the only remaining startup-fatal
|
|
/// gate is the one under test.
|
|
#[test]
|
|
#[ignore = "requires PostgreSQL"]
|
|
fn unreachable_redis_fails_boot_before_the_health_listener_binds() {
|
|
let database_url = std::env::var("DATABASE_URL")
|
|
.expect("postgres lane provides DATABASE_URL for each test process");
|
|
let redis_url = format!("redis://127.0.0.1:{}", reserve_closed_port());
|
|
let metrics_port = reserve_closed_port().to_string();
|
|
let health_port = reserve_closed_port();
|
|
let health_port_value = health_port.to_string();
|
|
|
|
let (exited, output) = run_until_exit(
|
|
&[
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &metrics_port),
|
|
("BUZZ_HEALTH_PORT", &health_port_value),
|
|
("DATABASE_URL", &database_url),
|
|
("REDIS_URL", &redis_url),
|
|
("BUZZ_GIT_CONFORMANCE_PROBE", "false"),
|
|
],
|
|
CHILD_TIMEOUT,
|
|
);
|
|
let logs = format!(
|
|
"{}{}",
|
|
String::from_utf8_lossy(&output.stdout),
|
|
String::from_utf8_lossy(&output.stderr)
|
|
);
|
|
|
|
assert!(
|
|
!logs.contains("Health probe listener started"),
|
|
"the Redis bootstrap gate must run before the health listener binds: {logs}"
|
|
);
|
|
assert!(
|
|
exited && !output.status.success(),
|
|
"an unreachable Redis command path must be startup-fatal: {logs}"
|
|
);
|
|
assert!(
|
|
logs.contains(REDIS_BOOTSTRAP_FAILURE),
|
|
"the failure must name the gate that rejected boot: {logs}"
|
|
);
|
|
assert!(
|
|
TcpListener::bind(("0.0.0.0", health_port)).is_ok(),
|
|
"the health port must never have been bound"
|
|
);
|
|
}
|
|
|
|
/// A peer that accepts the socket but withholds its Redis response exercises
|
|
/// the outer timeout around both lazy pool checkout and PING. Removing or
|
|
/// narrowing that timeout makes this test kill a still-running relay at the
|
|
/// deadline instead of observing a startup failure.
|
|
#[test]
|
|
#[ignore = "requires PostgreSQL"]
|
|
fn hanging_redis_peer_times_out_before_the_health_listener_binds() {
|
|
let database_url = std::env::var("DATABASE_URL")
|
|
.expect("postgres lane provides DATABASE_URL for each test process");
|
|
let redis_peer = HangingRedisPeer::spawn();
|
|
let metrics_port = reserve_closed_port().to_string();
|
|
let health_port = reserve_closed_port();
|
|
let health_port_value = health_port.to_string();
|
|
let timeout = REDIS_BOOTSTRAP_BUDGET + REDIS_BOOTSTRAP_SCHEDULING_SLACK;
|
|
let started_at = Instant::now();
|
|
|
|
let (exited, output) = run_until_exit(
|
|
&[
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &metrics_port),
|
|
("BUZZ_HEALTH_PORT", &health_port_value),
|
|
("DATABASE_URL", &database_url),
|
|
("REDIS_URL", redis_peer.redis_url()),
|
|
("BUZZ_GIT_CONFORMANCE_PROBE", "false"),
|
|
],
|
|
timeout,
|
|
);
|
|
let elapsed = started_at.elapsed();
|
|
let logs = format!(
|
|
"{}{}",
|
|
String::from_utf8_lossy(&output.stdout),
|
|
String::from_utf8_lossy(&output.stderr)
|
|
);
|
|
redis_peer.assert_request_received(&logs);
|
|
|
|
assert!(
|
|
elapsed >= REDIS_BOOTSTRAP_BUDGET,
|
|
"the fake peer must hold the request through the bootstrap budget: {elapsed:?}: {logs}"
|
|
);
|
|
assert!(
|
|
exited && elapsed < timeout && !output.status.success(),
|
|
"the outer bootstrap timeout must terminate the relay within scheduling slack: {elapsed:?}: {logs}"
|
|
);
|
|
assert!(
|
|
logs.contains(REDIS_BOOTSTRAP_FAILURE),
|
|
"the timeout must report the bounded Redis bootstrap failure: {logs}"
|
|
);
|
|
assert!(
|
|
!logs.contains("Health probe listener started"),
|
|
"the health listener must not bind before Redis bootstrap succeeds: {logs}"
|
|
);
|
|
assert!(
|
|
TcpListener::bind(("0.0.0.0", health_port)).is_ok(),
|
|
"the health port must never have been bound"
|
|
);
|
|
}
|
|
|
|
/// Startup is the only owner of dependency evaluation. `/_status` just reads
|
|
/// the cache, a readiness probe records no dependency attempt at all, and no
|
|
/// request path may start a check — so if `main` stops spawning the sampler,
|
|
/// this pod evaluates Postgres, Redis, and the deletion catalog exactly
|
|
/// never: the dependency families stay absent from its scrape and `/_status`
|
|
/// answers `not_yet_sampled` for the pod's whole life.
|
|
///
|
|
/// No in-process test can fail on that, because each one drives `sample`
|
|
/// itself. This one boots the real binary against real dependencies and
|
|
/// reads only the relay's own `/metrics` — no probe, no `/_status`, nothing
|
|
/// that could evaluate a dependency on the test's behalf. The first tick
|
|
/// fires immediately, so the wait is bounded by
|
|
/// [`METRICS_SCRAPE_DEADLINE`] and never a fixed sleep.
|
|
///
|
|
/// The completion-timestamp gauge is the needle because `sample` writes it
|
|
/// last, after the cache already serves the report: observing it proves the
|
|
/// whole cycle ran, with no window where the counters have landed but the
|
|
/// timestamp has not.
|
|
#[test]
|
|
#[ignore = "requires PostgreSQL"]
|
|
fn startup_owns_the_dependency_sampler() {
|
|
let database_url = std::env::var("DATABASE_URL")
|
|
.expect("postgres lane provides DATABASE_URL for each test process");
|
|
let redis_url = std::env::var("REDIS_URL")
|
|
.expect("the postgres lane runs alongside Redis and exports REDIS_URL");
|
|
let metrics_port = reserve_closed_port();
|
|
let metrics_port_value = metrics_port.to_string();
|
|
let health_port_value = reserve_closed_port().to_string();
|
|
let bind_addr = format!("127.0.0.1:{}", reserve_closed_port());
|
|
|
|
let mut process = RelayProcess::spawn(&[
|
|
("BUZZ_RELAY_PRIVATE_KEY", VALID_RELAY_PRIVATE_KEY),
|
|
("BUZZ_METRICS_PORT", &metrics_port_value),
|
|
("BUZZ_HEALTH_PORT", &health_port_value),
|
|
("BUZZ_BIND_ADDR", &bind_addr),
|
|
("DATABASE_URL", &database_url),
|
|
("REDIS_URL", &redis_url),
|
|
("BUZZ_GIT_CONFORMANCE_PROBE", "false"),
|
|
]);
|
|
let scrape = wait_for_scraped_metric(
|
|
&mut process,
|
|
metrics_port,
|
|
"buzz_readiness_dependency_sample_completed_timestamp_seconds",
|
|
);
|
|
let output = process.terminate();
|
|
let logs = format!(
|
|
"{}{}",
|
|
String::from_utf8_lossy(&output.stdout),
|
|
String::from_utf8_lossy(&output.stderr)
|
|
);
|
|
|
|
assert!(
|
|
scrape.contains("buzz_readiness_dependency_checks_total{"),
|
|
"the same cycle must publish its per-dependency outcomes: {scrape}"
|
|
);
|
|
assert!(
|
|
scrape.contains("buzz_readiness_check_duration_seconds"),
|
|
"a completed evaluation must publish its latency too: {scrape}"
|
|
);
|
|
assert!(
|
|
!scrape.contains("buzz_readiness_checks_total{"),
|
|
"no readiness probe was sent, so the sampler alone produced this: {scrape}"
|
|
);
|
|
assert!(
|
|
logs.contains("Health probe listener started"),
|
|
"the sampler must be owned by a relay that finished booting: {logs}"
|
|
);
|
|
}
|
|
}
|