From 01e258efd89b4241a847706a17bfb8a5b302eb1b Mon Sep 17 00:00:00 2001 From: mfw78 Date: Wed, 26 Aug 2026 00:53:32 +0000 Subject: [PATCH 1/5] feat(supervisor): count fuel-set drops and sample latency on every outcome DispatchOutcome::FuelSetFailed was logged and never counted. It now increments nexum_runtime_dispatch_dropped_total with reason "fuel_set_failed", beside the existing shutdown and rate_limited reasons. nexum_runtime_dispatch_latency_seconds was recorded in the success arm alone, so a fault, a trap or a deadline hit contributed no sample and p95 read low exactly when dispatch was failing. The histogram is now recorded once, after the match, for every dispatch that reached the guest, labelled outcome = ok, fault, trap or deadline. A deadline hit stays fatal like a trap and carries its own label so a blocked host call is legible apart from a guest trap. Cardinality is eleven buckets per module and outcome pair, over four fixed outcome values. Neither metric name is new, so the METRICS table is unchanged and the name guard is untouched. The exporter matches its bucket list on the bare metric name, which the addons test now records an outcome label to prove, and the NexumDispatchLatency alert sums by (module, le), so the added label costs neither its bounds nor its reading. Closes #368 AI Assistance: Claude Code used for implementation, tests and docs. --- .../src/supervisor/dispatch.rs | 99 +++++++++--- .../src/supervisor/tests/dispatch.rs | 148 ++++++++++++++++++ .../src/supervisor/tests/mod.rs | 2 +- .../src/test_utils/mod.rs | 2 +- crates/nexum-runtime/src/addons.rs | 7 +- docs/production.md | 4 +- 6 files changed, 234 insertions(+), 28 deletions(-) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs index 09c9e1b8..d521131f 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs @@ -312,19 +312,18 @@ impl>> Supervisor { "nexum_runtime_dispatch_dropped_total", "module" => module.name.to_string(), "trigger_kind" => trigger_kind, - "reason" => "rate_limited", + "reason" => DispatchOutcome::RateLimited.label(), ) .increment(1); return DispatchOutcome::RateLimited; } - if let Err(e) = module.live.store.set_fuel(module.seed.spec.fuel) { - error!( - module = %module.name, - chain_id, - trigger_kind, - error = %e, - "set_fuel failed - skipping" - ); + if !refuel( + &mut module.live.store, + module.seed.spec.fuel, + &module.name, + chain_id, + trigger_kind, + ) { return DispatchOutcome::FuelSetFailed; } let start = Instant::now(); @@ -335,16 +334,16 @@ impl>> Supervisor { .live .bindings .call_on_trigger(&mut module.live.store, trigger); - let outcome = with_dispatch_deadline(deadline, call) - .await - .unwrap_or_else(|exceeded| Err(wasmtime::Error::from(exceeded))); + let bounded = with_dispatch_deadline(deadline, call).await; + let deadline_hit = bounded.is_err(); + let result = bounded.unwrap_or_else(|exceeded| Err(wasmtime::Error::from(exceeded))); // One post-call sample: the trap instant is start plus elapsed, not // the pre-dispatch `now`. This is the same clock the lifecycle // reads, so under `start_paused` the latency histogram records the // virtual elapsed time: do not assert on it from a paused test. let elapsed = start.elapsed(); let latency_ms = elapsed.as_millis() as u64; - match outcome { + let outcome = match result { Ok(Ok(())) => { debug!( module = %module.name, @@ -354,12 +353,6 @@ impl>> Supervisor { latency_ms, "dispatch ok" ); - metrics::histogram!( - "nexum_runtime_dispatch_latency_seconds", - "module" => module.name.to_string(), - "trigger_kind" => trigger_kind, - ) - .record(elapsed.as_secs_f64()); module.health.dispatch_succeeded(); DispatchOutcome::Ok } @@ -416,12 +409,56 @@ impl>> Supervisor { if let Some(recent) = verdict.poisoned { report_poison(&module.name, recent, poison_policy.window, trap.to_string()); } - DispatchOutcome::Trapped + if deadline_hit { + DispatchOutcome::Deadline + } else { + DispatchOutcome::Trapped + } } - } + }; + // Every outcome that entered the guest contributes a sample: a + // success-only histogram reads p95 low exactly when dispatch is + // failing. + metrics::histogram!( + "nexum_runtime_dispatch_latency_seconds", + "module" => module.name.to_string(), + "trigger_kind" => trigger_kind, + "outcome" => outcome.label(), + ) + .record(elapsed.as_secs_f64()); + outcome } } +/// Grants the dispatch its fuel budget; `false` means the trigger never +/// reached the guest and was counted as a drop. +pub(super) fn refuel( + store: &mut wasmtime::Store, + fuel: u64, + module: &ModuleId, + chain_id: u64, + trigger_kind: &'static str, +) -> bool { + let Err(e) = store.set_fuel(fuel) else { + return true; + }; + error!( + module = %module, + chain_id, + trigger_kind, + error = %e, + "set_fuel failed - skipping" + ); + metrics::counter!( + "nexum_runtime_dispatch_dropped_total", + "module" => module.clone(), + "trigger_kind" => trigger_kind, + "reason" => DispatchOutcome::FuelSetFailed.label(), + ) + .increment(1); + false +} + /// The poison-transition trio: quarantine warn plus gauge, with the trap /// that crossed the threshold. fn report_poison(name: &ModuleId, recent_failures: u32, window: Duration, last_error: String) { @@ -459,15 +496,33 @@ pub(super) async fn with_dispatch_deadline( .map_err(|_elapsed| DeadlineExceeded(deadline)) } -#[derive(Debug)] +#[derive(Debug, Clone, Copy)] pub(super) enum DispatchOutcome { Ok, /// Guest returned a typed `fault` via WIT, not a trap; the module stays alive. Fault, /// Marked dead, maybe quarantined per the poison policy. Trapped, + /// Cut off at the wall-clock deadline; handled like a trap. + Deadline, /// `set_fuel` failed before the call; the module stays alive, the trigger skips. FuelSetFailed, /// Dropped before the guest runs; liveness untouched. RateLimited, } + +impl DispatchOutcome { + /// The `outcome` label on the latency histogram; the two pre-guest + /// drops carry theirs as the `reason` on + /// `nexum_runtime_dispatch_dropped_total` instead. + pub(super) fn label(self) -> &'static str { + match self { + Self::Ok => "ok", + Self::Fault => "fault", + Self::Trapped => "trap", + Self::Deadline => "deadline", + Self::FuelSetFailed => "fuel_set_failed", + Self::RateLimited => "rate_limited", + } + } +} diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs index 69dfc511..97e6091c 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs @@ -2,6 +2,7 @@ use super::*; use crate::engine_config::DispatchLimitsSection; +use crate::test_utils::{Sample, capture_metrics, samples_named}; fn deadline_secs(secs: u64) -> DispatchLimitsSection { DispatchLimitsSection { @@ -10,6 +11,26 @@ fn deadline_secs(secs: u64) -> DispatchLimitsSection { } } +/// The `outcome` label of every latency sample recorded. +fn latency_outcomes(samples: &[Sample]) -> Vec<&str> { + samples_named(samples, "nexum_runtime_dispatch_latency_seconds") + .into_iter() + .flat_map(|sample| sample.labels.iter()) + .filter(|(key, _)| key == "outcome") + .map(|(_, value)| value.as_str()) + .collect() +} + +/// The capture recorder is thread-local, so the dispatch has to run on the +/// capturing thread rather than a spawned worker. +fn block_on_current_thread(f: F) -> F::Output { + tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("current-thread runtime") + .block_on(f) +} + #[test] fn module_limits_default_to_policy_ceilings_when_unset() { let cfg = PolicyCeilings::default(); @@ -543,3 +564,130 @@ async fn multi_chain_poisoned_module_does_not_affect_other_chains() { assert_eq!(booted.supervisor.alive_count(), 1, "only example is alive"); assert_eq!(booted.supervisor.poisoned_count(), 1); } + +/// fuel-bomb traps on chain 1; the example succeeds on chain 100. +#[test] +fn a_trap_and_a_success_each_record_a_labelled_latency_sample() { + let Some(bomb_wasm) = module_wasm_or_skip("fuel-bomb") else { + return; + }; + let Some(example_wasm) = example_wasm_or_skip() else { + return; + }; + let ((), samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = scenario() + .module( + Entry::new(workspace_manifest( + "modules/fixtures/fuel-bomb/component.toml", + )) + .wasm(bomb_wasm), + ) + .module( + Entry::new( + TestManifest::new("example") + .cap("logging") + .block_trigger(100), + ) + .wasm(example_wasm), + ) + .boot() + .await + .expect("boot"); + booted.dispatch_block_on(1).await; + assert_eq!(booted.dispatch_block_on(100).await, 1, "the example ran"); + }) + }); + let outcomes = latency_outcomes(&samples); + assert!(outcomes.contains(&"trap"), "{samples:?}"); + assert!(outcomes.contains(&"ok"), "{samples:?}"); +} + +/// slow-host parks its one host call an hour past the 1 s deadline, so +/// the dispatch ends fatally like a trap and carries its own label. +#[test] +fn a_deadline_hit_records_a_latency_sample_labelled_deadline() { + let Some(wasm) = module_wasm_or_skip("slow-host") else { + return; + }; + let node = crate::test_utils::FakeNode::new(); + node.on_method(nexum_world::ChainMethod::EthBlockNumber, "\"0x1\""); + node.delay_next_request(Duration::from_secs(3600)); + let (dispatched, samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = BootScenario::over(crate::test_utils::mock_components_from( + &node, + crate::test_utils::MockStateStore::new(), + )) + .limits(limits_with(|limits| limits.dispatch = deadline_secs(1))) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots"); + // The park is an hour past the 1 s deadline; pausing here waits + // out neither. + tokio::time::pause(); + booted.dispatch_block_on(1).await + }) + }); + assert_eq!(dispatched, 0, "the deadline cut the blocked host call off"); + assert!( + latency_outcomes(&samples).contains(&"deadline"), + "{samples:?}", + ); +} + +/// A zero state quota faults the fixture's first store write, which the +/// guest returns as a typed WIT fault rather than trapping. +#[test] +fn a_fault_records_a_latency_sample_labelled_fault() { + let Some(wasm) = module_wasm_or_skip("flaky-bomb") else { + return; + }; + let ((dispatched, alive), samples) = capture_metrics(|| { + block_on_current_thread(async { + let mut booted = scenario() + .policy(PolicySection { + ceilings: PolicyCeilings { + max_state_bytes: 0, + ..PolicyCeilings::default() + }, + ..PolicySection::default() + }) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/flaky-bomb/component.toml", + )) + .boot() + .await + .expect("flaky-bomb boots"); + let dispatched = booted.dispatch_block_on(1).await; + (dispatched, booted.supervisor.alive_count()) + }) + }); + assert_eq!(dispatched, 0, "the quota refused the store write"); + assert_eq!(alive, 1, "a fault leaves the module alive"); + assert!(latency_outcomes(&samples).contains(&"fault"), "{samples:?}"); +} + +/// An engine without fuel metering is the only way `set_fuel` fails. +#[test] +fn a_failed_fuel_set_is_counted_as_a_drop() { + let engine = wasmtime::Engine::default(); + let mut store = wasmtime::Store::new(&engine, ()); + let module = nexum_primitives::module_id::ModuleId::parse("m").expect("a plain name parses"); + let (granted, samples) = capture_metrics(|| refuel(&mut store, 1_000, &module, 1, "block")); + assert!(!granted, "an engine without fuel cannot be refuelled"); + let hits = samples_named(&samples, "nexum_runtime_dispatch_dropped_total"); + assert_eq!(hits.len(), 1, "one drop counted: {samples:?}"); + assert!( + hits[0].has_label("reason", "fuel_set_failed") + && hits[0].has_label("module", "m") + && hits[0].has_label("trigger_kind", "block"), + "{:?}", + hits[0].labels, + ); +} diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs index a0762585..4490e5e9 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs @@ -20,7 +20,7 @@ use super::artifact::{DigestPolicy, read_verified_component}; use super::cursors::{ chainlog_cursor_key, commit_chain_log_cursor, commit_chain_log_frontier, read_chain_log_cursor, }; -use super::dispatch::with_dispatch_deadline; +use super::dispatch::{refuel, with_dispatch_deadline}; use super::prepass::{ NamespaceLedger, claim_namespace, enforce_total_reservation, unconfigured_chain, }; diff --git a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs index c3f65720..54512d78 100644 --- a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs +++ b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs @@ -16,7 +16,7 @@ pub(crate) use nexum_runtime_testing::{ #[cfg(test)] pub(crate) use nexum_runtime_testing::{ - FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, capture_metrics, + FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, Sample, capture_metrics, example_wasm_or_skip, linked_block, metrics_util, mock_components, mock_components_from, mocked_pool, module_wasm_or_skip, rpc_err, rpc_head, rpc_ok, samples_named, test_hash, workspace_root, diff --git a/crates/nexum-runtime/src/addons.rs b/crates/nexum-runtime/src/addons.rs index c2a2280e..eab998f3 100644 --- a/crates/nexum-runtime/src/addons.rs +++ b/crates/nexum-runtime/src/addons.rs @@ -125,7 +125,9 @@ mod tests { use crate::test_utils::Refusal; /// The `NexumDispatchLatency` alert reads `_bucket` series by `le`, so - /// the latency metric must render as a Prometheus histogram. + /// the latency metric must render as a Prometheus histogram. The bucket + /// list is matched on the bare name, so the call site's labels, which + /// the dispatch path adds to, cannot cost it its bounds. #[test] fn the_latency_histogram_renders_bucket_series() { const NAME: &str = "nexum_runtime_dispatch_latency_seconds"; @@ -134,7 +136,8 @@ mod tests { .build_recorder(); let handle = recorder.handle(); metrics::with_local_recorder(&recorder, || { - metrics::histogram!(NAME, "module" => "m", "trigger_kind" => "block").record(0.5); + metrics::histogram!(NAME, "module" => "m", "trigger_kind" => "block", "outcome" => "trap") + .record(0.5); }); let rendered = handle.render(); assert!( diff --git a/docs/production.md b/docs/production.md index 5392f6a9..e902aaec 100644 --- a/docs/production.md +++ b/docs/production.md @@ -188,8 +188,8 @@ With `enabled = false` the recorder is still installed, so call sites stay live, | Metric | Type | Labels | Meaning | |---|---|---|---| | `nexum_runtime_boot_refusals_total` | counter | `error_kind` | Boot refusals by error kind. | -| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind` | Wall-clock seconds to dispatch one trigger. | -| `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. A block is not replayed; an event is, from its cursor. | +| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind`, `outcome` | Wall-clock seconds to dispatch one trigger, sampled on every dispatch that reached the guest. `outcome` is one of `ok`, `fault`, `trap` and `deadline`, so a p95 read over the bare metric covers the failing dispatches too; sum `outcome` away to read one module's whole distribution, as `NexumDispatchLatency` below does. A trigger dropped before the guest runs records no latency and is counted in `nexum_runtime_dispatch_dropped_total` instead. Eleven buckets per module and outcome pair, with the four values fixed. | +| `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. `reason = "fuel_set_failed"` is the per-dispatch fuel budget failing to apply: the module stays alive and the trigger is skipped. A block is not replayed; an event is, from its cursor. | | `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap; other values are fault labels. | | `nexum_runtime_module_restarts_total` | counter | `module` | Module restart attempts. | | `nexum_runtime_module_poisoned` | gauge | `module` | `1` once a module crosses `[limits.poison]` (default 5 failures in 600 s) or its event source reports an unrecoverable condition. Stays `1` until the process restarts. | From 482d706bc6feba87463c635f8e8ec311ae92f5e6 Mon Sep 17 00:00:00 2001 From: mfw78 Date: Wed, 26 Aug 2026 01:38:42 +0000 Subject: [PATCH 2/5] fix(observability): name the outcome label in the latency HELP and size its cardinality The METRICS table is the only in-band description an operator reads at /metrics, and its sibling entries name their labels. The dispatch latency HELP now names module and outcome like they do. The cardinality note in docs/production.md counted eleven buckets per module and outcome pair, which omits trigger_kind and the +Inf, _sum and _count series a Prometheus histogram also renders. It now states the multiplier the outcome label actually adds. The two capture_metrics tests that predate this branch built their current-thread runtime inline; they now use the block_on_current_thread helper the new tests introduced, so the file carries one form of the incantation. AI Assistance: Claude Code used for the red-team review and these fixes. --- crates/nexum-runtime-metrics/src/lib.rs | 2 +- .../src/supervisor/tests/dispatch.rs | 82 ++++++++----------- crates/nexum-runtime/src/addons.rs | 5 +- docs/production.md | 2 +- 4 files changed, 40 insertions(+), 51 deletions(-) diff --git a/crates/nexum-runtime-metrics/src/lib.rs b/crates/nexum-runtime-metrics/src/lib.rs index f052ff50..e3bb431b 100644 --- a/crates/nexum-runtime-metrics/src/lib.rs +++ b/crates/nexum-runtime-metrics/src/lib.rs @@ -65,7 +65,7 @@ pub const METRICS: &[Metric] = &[ Metric { name: "nexum_runtime_dispatch_latency_seconds", kind: Kind::Histogram, - help: "Wall-clock seconds to dispatch one trigger.", + help: "Wall-clock seconds to dispatch one trigger, by module and outcome.", }, Metric { name: "nexum_runtime_log_fields_dropped_total", diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs index 97e6091c..d8426e2e 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs @@ -280,29 +280,24 @@ async fn dispatch_deadline_cuts_off_a_blocked_host_call_and_recovers() { #[test] fn a_delivered_block_sets_the_last_delivered_gauge() { use crate::test_utils::metrics_util::debugging::DebugValue; - use crate::test_utils::{capture_metrics, samples_named}; let Some(wasm) = example_wasm_or_skip() else { return; }; let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module( - TestManifest::new("module-a") - .cap("logging") - .block_trigger(1), - ) - .boot() - .await - .expect("boot"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module( + TestManifest::new("module-a") + .cap("logging") + .block_trigger(1), + ) + .boot() + .await + .expect("boot"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1); let hits = samples_named(&samples, "nexum_runtime_chain_last_delivered_height"); @@ -319,39 +314,34 @@ fn a_delivered_block_sets_the_last_delivered_gauge() { #[test] fn an_older_delivery_does_not_lower_the_last_delivered_gauge() { use crate::test_utils::metrics_util::debugging::DebugValue; - use crate::test_utils::{capture_metrics, samples_named}; let Some(wasm) = example_wasm_or_skip() else { return; }; let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module( - TestManifest::new("module-a") - .cap("logging") - .block_trigger(1), - ) - .boot() - .await - .expect("boot"); - let newer = booted.dispatch_block_on(1).await; - let older = booted - .supervisor - .dispatch_block(nexum::host::types::Block { - chain_id: 1, - number: 18_000_000, - hash: vec![0xcd; 32], - timestamp: 1_700_000_000_000, - }) - .await; - newer + older - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module( + TestManifest::new("module-a") + .cap("logging") + .block_trigger(1), + ) + .boot() + .await + .expect("boot"); + let newer = booted.dispatch_block_on(1).await; + let older = booted + .supervisor + .dispatch_block(nexum::host::types::Block { + chain_id: 1, + number: 18_000_000, + hash: vec![0xcd; 32], + timestamp: 1_700_000_000_000, + }) + .await; + newer + older + }) }); assert_eq!(dispatched, 2, "both blocks reached the module"); let hits = samples_named(&samples, "nexum_runtime_chain_last_delivered_height"); diff --git a/crates/nexum-runtime/src/addons.rs b/crates/nexum-runtime/src/addons.rs index eab998f3..c694712c 100644 --- a/crates/nexum-runtime/src/addons.rs +++ b/crates/nexum-runtime/src/addons.rs @@ -125,9 +125,8 @@ mod tests { use crate::test_utils::Refusal; /// The `NexumDispatchLatency` alert reads `_bucket` series by `le`, so - /// the latency metric must render as a Prometheus histogram. The bucket - /// list is matched on the bare name, so the call site's labels, which - /// the dispatch path adds to, cannot cost it its bounds. + /// the latency metric must render as a Prometheus histogram. Bounds are + /// matched on the bare name, so call-site labels cannot cost them. #[test] fn the_latency_histogram_renders_bucket_series() { const NAME: &str = "nexum_runtime_dispatch_latency_seconds"; diff --git a/docs/production.md b/docs/production.md index e902aaec..93df55fe 100644 --- a/docs/production.md +++ b/docs/production.md @@ -188,7 +188,7 @@ With `enabled = false` the recorder is still installed, so call sites stay live, | Metric | Type | Labels | Meaning | |---|---|---|---| | `nexum_runtime_boot_refusals_total` | counter | `error_kind` | Boot refusals by error kind. | -| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind`, `outcome` | Wall-clock seconds to dispatch one trigger, sampled on every dispatch that reached the guest. `outcome` is one of `ok`, `fault`, `trap` and `deadline`, so a p95 read over the bare metric covers the failing dispatches too; sum `outcome` away to read one module's whole distribution, as `NexumDispatchLatency` below does. A trigger dropped before the guest runs records no latency and is counted in `nexum_runtime_dispatch_dropped_total` instead. Eleven buckets per module and outcome pair, with the four values fixed. | +| `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind`, `outcome` | Wall-clock seconds to dispatch one trigger, sampled on every dispatch that reached the guest. `outcome` is one of `ok`, `fault`, `trap` and `deadline`, so a p95 read over the bare metric covers the failing dispatches too; sum `outcome` away to read one module's whole distribution, as `NexumDispatchLatency` below does. A trigger dropped before the guest runs records no latency and is counted in `nexum_runtime_dispatch_dropped_total` instead. `outcome` is bounded at those four values, so it multiplies the series count by at most four: each `module`, `trigger_kind` and `outcome` triple carries the eleven buckets plus `+Inf`, `_sum` and `_count`. | | `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. `reason = "fuel_set_failed"` is the per-dispatch fuel budget failing to apply: the module stays alive and the trigger is skipped. A block is not replayed; an event is, from its cursor. | | `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap; other values are fault labels. | | `nexum_runtime_module_restarts_total` | counter | `module` | Module restart attempts. | From 11eb965acf540d60ac0bc63861838454a30d77b4 Mon Sep 17 00:00:00 2001 From: mfw78 Date: Wed, 26 Aug 2026 02:15:39 +0000 Subject: [PATCH 3/5] refactor(supervisor): derive the outcome label rather than matching it strum is already a workspace dependency this crate inherits, and nexum-runtime-wasm derives IntoStaticStr for exactly this: string labels on an enum. A hand-written match reinvented it and gave a second place for a variant to be added without its label. serialize_all covers every variant but Trapped, whose label is "trap" rather than the variant name. AI Assistance: claude-opus-5 used for the review pass. --- .../src/supervisor/dispatch.rs | 28 ++++++------------- 1 file changed, 8 insertions(+), 20 deletions(-) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs index d521131f..2f898237 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs @@ -312,7 +312,7 @@ impl>> Supervisor { "nexum_runtime_dispatch_dropped_total", "module" => module.name.to_string(), "trigger_kind" => trigger_kind, - "reason" => DispatchOutcome::RateLimited.label(), + "reason" => <&str>::from(DispatchOutcome::RateLimited), ) .increment(1); return DispatchOutcome::RateLimited; @@ -423,7 +423,7 @@ impl>> Supervisor { "nexum_runtime_dispatch_latency_seconds", "module" => module.name.to_string(), "trigger_kind" => trigger_kind, - "outcome" => outcome.label(), + "outcome" => <&str>::from(outcome), ) .record(elapsed.as_secs_f64()); outcome @@ -453,7 +453,7 @@ pub(super) fn refuel( "nexum_runtime_dispatch_dropped_total", "module" => module.clone(), "trigger_kind" => trigger_kind, - "reason" => DispatchOutcome::FuelSetFailed.label(), + "reason" => <&str>::from(DispatchOutcome::FuelSetFailed), ) .increment(1); false @@ -496,12 +496,16 @@ pub(super) async fn with_dispatch_deadline( .map_err(|_elapsed| DeadlineExceeded(deadline)) } -#[derive(Debug, Clone, Copy)] +/// The `outcome` label on the latency histogram; the two pre-guest drops carry +/// theirs as the `reason` on `nexum_runtime_dispatch_dropped_total` instead. +#[derive(Debug, Clone, Copy, strum::IntoStaticStr)] +#[strum(serialize_all = "snake_case")] pub(super) enum DispatchOutcome { Ok, /// Guest returned a typed `fault` via WIT, not a trap; the module stays alive. Fault, /// Marked dead, maybe quarantined per the poison policy. + #[strum(serialize = "trap")] Trapped, /// Cut off at the wall-clock deadline; handled like a trap. Deadline, @@ -510,19 +514,3 @@ pub(super) enum DispatchOutcome { /// Dropped before the guest runs; liveness untouched. RateLimited, } - -impl DispatchOutcome { - /// The `outcome` label on the latency histogram; the two pre-guest - /// drops carry theirs as the `reason` on - /// `nexum_runtime_dispatch_dropped_total` instead. - pub(super) fn label(self) -> &'static str { - match self { - Self::Ok => "ok", - Self::Fault => "fault", - Self::Trapped => "trap", - Self::Deadline => "deadline", - Self::FuelSetFailed => "fuel_set_failed", - Self::RateLimited => "rate_limited", - } - } -} From 6ae8987dd081e3ad6988cc3c6c25ea2eeb089b36 Mon Sep 17 00:00:00 2001 From: mfw78 Date: Wed, 26 Aug 2026 02:33:46 +0000 Subject: [PATCH 4/5] fix(observability): label a deadline hit a deadline on both metrics The error counter hardcoded error_kind = "trap" in the arm that also handles a dispatch cut off at the deadline, while the latency histogram called the same event outcome = "deadline". A dashboard joining the two on what it took to be one failure got two answers. Both now read the same variant, so they cannot drift again. A deadline is a limit doing its job rather than a module bug, so NexumModuleTraps deliberately stops counting one, and the metric row and the alert say so. AI Assistance: claude-opus-5 used for the fix and the docs. --- .../src/supervisor/dispatch.rs | 16 ++++++++++------ .../src/supervisor/tests/dispatch.rs | 9 +++++++++ docs/production.md | 5 ++++- 3 files changed, 23 insertions(+), 7 deletions(-) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs index 2f898237..3c15e1fb 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/dispatch.rs @@ -381,6 +381,14 @@ impl>> Supervisor { let died_at = start + elapsed; let seed = crate::runtime::restart_policy::jitter_seed(module.name.as_str()); let verdict = module.health.record_trap(died_at, poison_policy, seed); + // One label for one event: the histogram's outcome and this + // counter's kind come from the same variant, so a deadline + // cannot read as a bug on one metric and a limit on the other. + let outcome = if deadline_hit { + DispatchOutcome::Deadline + } else { + DispatchOutcome::Trapped + }; error!( module = %module.name, chain_id, @@ -395,7 +403,7 @@ impl>> Supervisor { metrics::counter!( "nexum_runtime_module_errors_total", "module" => module.name.clone(), - "error_kind" => "trap", + "error_kind" => <&str>::from(outcome), ) .increment(1); // Leave a retrievable panic record on the dead run; the full @@ -409,11 +417,7 @@ impl>> Supervisor { if let Some(recent) = verdict.poisoned { report_poison(&module.name, recent, poison_policy.window, trap.to_string()); } - if deadline_hit { - DispatchOutcome::Deadline - } else { - DispatchOutcome::Trapped - } + outcome } }; // Every outcome that entered the guest contributes a sample: a diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs index d8426e2e..db0fc6b4 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs @@ -628,6 +628,15 @@ fn a_deadline_hit_records_a_latency_sample_labelled_deadline() { latency_outcomes(&samples).contains(&"deadline"), "{samples:?}", ); + let errors = samples_named(&samples, "nexum_runtime_module_errors_total"); + assert!( + errors.iter().any(|s| s.has_label("error_kind", "deadline")), + "{samples:?}", + ); + assert!( + !errors.iter().any(|s| s.has_label("error_kind", "trap")), + "a deadline is a limit, not a trap: {samples:?}", + ); } /// A zero state quota faults the fixture's first store write, which the diff --git a/docs/production.md b/docs/production.md index 93df55fe..453c6940 100644 --- a/docs/production.md +++ b/docs/production.md @@ -190,7 +190,7 @@ With `enabled = false` the recorder is still installed, so call sites stay live, | `nexum_runtime_boot_refusals_total` | counter | `error_kind` | Boot refusals by error kind. | | `nexum_runtime_dispatch_latency_seconds` | histogram | `module`, `trigger_kind`, `outcome` | Wall-clock seconds to dispatch one trigger, sampled on every dispatch that reached the guest. `outcome` is one of `ok`, `fault`, `trap` and `deadline`, so a p95 read over the bare metric covers the failing dispatches too; sum `outcome` away to read one module's whole distribution, as `NexumDispatchLatency` below does. A trigger dropped before the guest runs records no latency and is counted in `nexum_runtime_dispatch_dropped_total` instead. `outcome` is bounded at those four values, so it multiplies the series count by at most four: each `module`, `trigger_kind` and `outcome` triple carries the eleven buckets plus `+Inf`, `_sum` and `_count`. | | `nexum_runtime_dispatch_dropped_total` | counter | `module`, `trigger_kind`, `reason` | Triggers dropped before dispatch. `reason = "rate_limited"` is the per-component dispatch rate limit (`[limits.dispatch]`, default `burst = 256` and `refill_per_sec = 128`). `reason = "shutdown"` is a stop landing mid fan-out: the fan-out follows `[[modules]]` order, so the same trailing modules are skipped at every stop. `reason = "fuel_set_failed"` is the per-dispatch fuel budget failing to apply: the module stays alive and the trigger is skipped. A block is not replayed; an event is, from its cursor. | -| `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap; other values are fault labels. | +| `nexum_runtime_module_errors_total` | counter | `module`, `error_kind` | Module faults and traps. `error_kind = "trap"` is a wasmtime trap and `"deadline"` is a dispatch cut off at `[limits.dispatch] deadline_secs`; other values are fault labels. The trap and deadline values are the same strings the latency histogram uses for `outcome`, so the two metrics agree about one event. | | `nexum_runtime_module_restarts_total` | counter | `module` | Module restart attempts. | | `nexum_runtime_module_poisoned` | gauge | `module` | `1` once a module crosses `[limits.poison]` (default 5 failures in 600 s) or its event source reports an unrecoverable condition. Stays `1` until the process restarts. | | `nexum_runtime_module_unverified` | gauge | `module` | `1` for a module loaded with neither a `[[modules]].digest` nor a `[component].digest`, so nothing checked its bytes. Set once at boot and never cleared; a pinned module emits no series, so `sum` is the fleet's unverified count. Reaching this state at all needs `require_component_digest = false`, or a single-wasm command-line override. | @@ -237,6 +237,9 @@ groups: annotations: summary: "Nexum module {{ $labels.module }} is running unverified; pin its digest in engine.toml" + # A deadline is a limit doing its job, so it is deliberately not here. + # Alert on error_kind="deadline" separately if a module should never + # reach one. - alert: NexumModuleTraps expr: rate(nexum_runtime_module_errors_total{error_kind="trap"}[5m]) > 0 for: 5m From f6a25bbfdfa3752f238262d63147ad52ab710e09 Mon Sep 17 00:00:00 2001 From: mfw78 Date: Wed, 26 Aug 2026 03:05:15 +0000 Subject: [PATCH 5/5] refactor(testing): share the current-thread block_on the capture needs The runtime-builder incantation was open-coded eight times across four files before this branch, which then added a ninth as a local helper. It belongs beside capture_metrics, which is what makes it necessary: the recorder is thread-local, so work driven on another runtime's worker records into a different one and the capture comes back empty. Five of the eight now call the shared function. The three in event_loop.rs add start_paused(true) and are left alone, because another branch is in that file. Named block_on_current_thread rather than block_on: the supervisor tests already have a block_on that builds a chain block. AI Assistance: claude-opus-5 used for the review pass. --- .../src/supervisor/tests/boot_refusals.rs | 6 +-- .../src/supervisor/tests/chain_gate.rs | 53 ++++++++----------- .../src/supervisor/tests/dispatch.rs | 10 ---- .../src/supervisor/tests/mod.rs | 5 +- .../src/test_utils/mod.rs | 8 +-- crates/nexum-runtime-testing/Cargo.toml | 2 +- crates/nexum-runtime-testing/src/lib.rs | 2 +- .../src/metrics_capture.rs | 13 +++++ 8 files changed, 45 insertions(+), 54 deletions(-) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs index d6050dbe..22b6c6a5 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/boot_refusals.rs @@ -18,11 +18,7 @@ fn a_boot_refusal_increments_the_counter_under_its_parse_class() { // Raw TOML: the textual absence of [dependencies] is the fixture. let manifest = "[component]\nname = \"example\"\n"; let (refusal, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(scenario().module(manifest.to_owned()).expect_refusal()) + block_on_current_thread(scenario().module(manifest.to_owned()).expect_refusal()) }); refusal.variant::(|e| { matches!(e, BootRefusal::Manifest(ParseError::MissingCapabilities)) diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs index 67621e84..a41dc8a7 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/chain_gate.rs @@ -244,21 +244,17 @@ fn a_guest_request_for_an_unconfigured_chain_counts_under_the_sentinel() { // `scenario()` boots over an empty pool while `test_chain_configs()` // still declares chain 1. let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = scenario() - .wasm(wasm) - .module(workspace_manifest( - "modules/fixtures/slow-host/component.toml", - )) - .boot() - .await - .expect("slow-host boots over the empty pool"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = scenario() + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots over the empty pool"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1, "the fixture swallows the request error"); let hits = samples_named(&samples, "nexum_runtime_chain_request_total"); @@ -288,22 +284,17 @@ fn a_guest_request_for_a_configured_chain_keeps_its_chain_id() { let node = FakeNode::new(); node.on_method(nexum_world::ChainMethod::EthBlockNumber, "\"0x1\""); let (dispatched, samples) = capture_metrics(|| { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(async { - let mut booted = - BootScenario::over(mock_components_from(&node, MockStateStore::new())) - .wasm(wasm) - .module(workspace_manifest( - "modules/fixtures/slow-host/component.toml", - )) - .boot() - .await - .expect("slow-host boots over the mocked pool"); - booted.dispatch_block_on(1).await - }) + block_on_current_thread(async { + let mut booted = BootScenario::over(mock_components_from(&node, MockStateStore::new())) + .wasm(wasm) + .module(workspace_manifest( + "modules/fixtures/slow-host/component.toml", + )) + .boot() + .await + .expect("slow-host boots over the mocked pool"); + booted.dispatch_block_on(1).await + }) }); assert_eq!(dispatched, 1); let hits = samples_named(&samples, "nexum_runtime_chain_request_total"); diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs index db0fc6b4..07daf3b7 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/dispatch.rs @@ -21,16 +21,6 @@ fn latency_outcomes(samples: &[Sample]) -> Vec<&str> { .collect() } -/// The capture recorder is thread-local, so the dispatch has to run on the -/// capturing thread rather than a spawned worker. -fn block_on_current_thread(f: F) -> F::Output { - tokio::runtime::Builder::new_current_thread() - .enable_all() - .build() - .expect("current-thread runtime") - .block_on(f) -} - #[test] fn module_limits_default_to_policy_ceilings_when_unset() { let cfg = PolicyCeilings::default(); diff --git a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs index 4490e5e9..ed986e83 100644 --- a/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs +++ b/crates/nexum-runtime-supervisor/src/supervisor/tests/mod.rs @@ -37,8 +37,9 @@ use crate::manifest::{self, CapabilityRegistry, ParseError, ResourceSection}; use crate::supervisor::load::LoadRefusal; use crate::supervisor::prepass::BootRefusal; use crate::test_utils::{ - BootScenario, Entry, LocalTypes, ManifestInput, Refusal, TestManifest, example_wasm_or_skip, - limits_with, mock_components, module_wasm_or_skip, test_wasmtime_engine, workspace_root, + BootScenario, Entry, LocalTypes, ManifestInput, Refusal, TestManifest, block_on_current_thread, + example_wasm_or_skip, limits_with, mock_components, module_wasm_or_skip, test_wasmtime_engine, + workspace_root, }; use nexum_primitives::digest::{ContentDigest, DigestMismatch}; use nexum_runtime_chain::ProviderPool; diff --git a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs index 54512d78..634dc2d3 100644 --- a/crates/nexum-runtime-supervisor/src/test_utils/mod.rs +++ b/crates/nexum-runtime-supervisor/src/test_utils/mod.rs @@ -16,10 +16,10 @@ pub(crate) use nexum_runtime_testing::{ #[cfg(test)] pub(crate) use nexum_runtime_testing::{ - FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, Sample, capture_metrics, - example_wasm_or_skip, linked_block, metrics_util, mock_components, mock_components_from, - mocked_pool, module_wasm_or_skip, rpc_err, rpc_head, rpc_ok, samples_named, test_hash, - workspace_root, + FakeNode, ManualClock, MockRpc, MockStateStore, MockTypes, Sample, block_on_current_thread, + capture_metrics, example_wasm_or_skip, linked_block, metrics_util, mock_components, + mock_components_from, mocked_pool, module_wasm_or_skip, rpc_err, rpc_head, rpc_ok, + samples_named, test_hash, workspace_root, }; #[cfg(test)] diff --git a/crates/nexum-runtime-testing/Cargo.toml b/crates/nexum-runtime-testing/Cargo.toml index 225ebcf6..2fdedcbe 100644 --- a/crates/nexum-runtime-testing/Cargo.toml +++ b/crates/nexum-runtime-testing/Cargo.toml @@ -30,7 +30,7 @@ nexum-world = { path = "../nexum-world" } parking_lot.workspace = true serde.workspace = true serde_json = { workspace = true, features = ["std"] } -tokio = { workspace = true, features = ["sync", "time"] } +tokio = { workspace = true, features = ["rt", "sync", "time"] } toml.workspace = true tower.workspace = true wasmtime-wasi.workspace = true diff --git a/crates/nexum-runtime-testing/src/lib.rs b/crates/nexum-runtime-testing/src/lib.rs index 166c8e9d..5abc9c0a 100644 --- a/crates/nexum-runtime-testing/src/lib.rs +++ b/crates/nexum-runtime-testing/src/lib.rs @@ -22,7 +22,7 @@ pub use alloy_transport::mock::MockResponse; pub use builders::Prebuilt; pub use clock::ManualClock; pub use manifest::{ManifestInput, TestManifest, manifest}; -pub use metrics_capture::{Sample, capture_metrics, samples_named}; +pub use metrics_capture::{Sample, block_on_current_thread, capture_metrics, samples_named}; pub use rpc::{ CapturedRpc, FakeNode, MockRpc, linked_block, mocked_pool, rpc_err, rpc_head, rpc_ok, test_hash, }; diff --git a/crates/nexum-runtime-testing/src/metrics_capture.rs b/crates/nexum-runtime-testing/src/metrics_capture.rs index 189a92e0..2d9868c5 100644 --- a/crates/nexum-runtime-testing/src/metrics_capture.rs +++ b/crates/nexum-runtime-testing/src/metrics_capture.rs @@ -56,6 +56,19 @@ pub fn samples_named<'a>(samples: &'a [Sample], name: &str) -> Vec<&'a Sample> { samples.iter().filter(|s| s.name == name).collect() } +/// Drive `f` to completion on the calling thread. +/// +/// [`capture_metrics`] installs a thread-local recorder, so work spawned onto +/// another runtime's worker records into a different one and the capture comes +/// back empty. +pub fn block_on_current_thread(f: F) -> F::Output { + tokio::runtime::Builder::new_current_thread() + .enable_all() + .build() + .expect("current-thread runtime") + .block_on(f) +} + #[cfg(test)] mod tests { use super::*;