From ae6cf1ef0f6f842e22882de61927aa5320c586b9 Mon Sep 17 00:00:00 2001 From: andrussal Date: Thu, 11 Dec 2025 08:32:06 +0100 Subject: [PATCH] Add richer logging across workloads --- testing-framework/workflows/src/workloads/chaos.rs | 14 +++++++++++--- .../workflows/src/workloads/da/expectation.rs | 9 +++++++-- .../workflows/src/workloads/da/workload.rs | 1 + .../src/workloads/transaction/expectation.rs | 3 +++ 4 files changed, 22 insertions(+), 5 deletions(-) diff --git a/testing-framework/workflows/src/workloads/chaos.rs b/testing-framework/workflows/src/workloads/chaos.rs index 3ed58d1..13889ce 100644 --- a/testing-framework/workflows/src/workloads/chaos.rs +++ b/testing-framework/workflows/src/workloads/chaos.rs @@ -69,9 +69,12 @@ impl RandomRestartWorkload { .unwrap_or_else(|| Duration::from_millis(1)) .as_secs_f64(); let offset = thread_rng().gen_range(0.0..=spread); - self.min_delay + let delay = self + .min_delay .checked_add(Duration::from_secs_f64(offset)) - .unwrap_or(self.max_delay) + .unwrap_or(self.max_delay); + tracing::debug!(delay_ms = delay.as_millis(), "chaos restart selected delay"); + delay } fn initialize_cooldowns(&self, targets: &[Target]) -> HashMap { @@ -99,6 +102,10 @@ impl RandomRestartWorkload { { let wait = next_ready.saturating_duration_since(now); if !wait.is_zero() { + tracing::debug!( + wait_ms = wait.as_millis(), + "chaos restart waiting for cooldown" + ); sleep(wait).await; continue; } @@ -111,6 +118,7 @@ impl RandomRestartWorkload { .collect(); if let Some(choice) = available.choose(&mut thread_rng()).copied() { + tracing::debug!(?choice, "chaos restart picked target"); return choice; } @@ -174,7 +182,7 @@ impl Workload for RandomRestartWorkload { } } -#[derive(Clone, Copy, PartialEq, Eq, Hash)] +#[derive(Clone, Copy, PartialEq, Eq, Hash, Debug)] enum Target { Validator(usize), Executor(usize), diff --git a/testing-framework/workflows/src/workloads/da/expectation.rs b/testing-framework/workflows/src/workloads/da/expectation.rs index c31c7ec..c08b32d 100644 --- a/testing-framework/workflows/src/workloads/da/expectation.rs +++ b/testing-framework/workflows/src/workloads/da/expectation.rs @@ -86,8 +86,13 @@ impl Expectation for DaWorkloadExpectation { &inscriptions_for_task, &blobs_for_task, ), - Err(broadcast::error::RecvError::Lagged(_)) => {} - Err(broadcast::error::RecvError::Closed) => break, + Err(broadcast::error::RecvError::Lagged(skipped)) => { + tracing::debug!(skipped, "DA expectation: receiver lagged"); + } + Err(broadcast::error::RecvError::Closed) => { + tracing::debug!("DA expectation: block feed closed"); + break; + } } } }); diff --git a/testing-framework/workflows/src/workloads/da/workload.rs b/testing-framework/workflows/src/workloads/da/workload.rs index a35cb61..ef6f2da 100644 --- a/testing-framework/workflows/src/workloads/da/workload.rs +++ b/testing-framework/workflows/src/workloads/da/workload.rs @@ -74,6 +74,7 @@ impl ScenarioWorkload for Workload { for channel_id in self.plan().iter().copied() { tracing::info!(channel_id = ?channel_id, "DA workload starting channel flow"); run_channel_flow(ctx, &mut receiver, channel_id).await?; + tracing::info!(channel_id = ?channel_id, "DA workload finished channel flow"); } tracing::info!("DA workload completed all channel flows"); diff --git a/testing-framework/workflows/src/workloads/transaction/expectation.rs b/testing-framework/workflows/src/workloads/transaction/expectation.rs index 5e32245..0be5763 100644 --- a/testing-framework/workflows/src/workloads/transaction/expectation.rs +++ b/testing-framework/workflows/src/workloads/transaction/expectation.rs @@ -104,6 +104,7 @@ impl Expectation for TxInclusionExpectation { tokio::spawn(async move { let mut receiver = receiver; let genesis_parent = HeaderId::from([0; 32]); + tracing::debug!("tx inclusion capture task started"); loop { match receiver.recv().await { Ok(record) => { @@ -115,6 +116,7 @@ impl Expectation for TxInclusionExpectation { for note in &tx.mantle_tx().ledger_tx.outputs { if spawn_accounts.contains(¬e.pk) { spawn_observed.fetch_add(1, Ordering::Relaxed); + tracing::debug!(pk = ?note.pk, "tx inclusion observed account output"); break; } } @@ -124,6 +126,7 @@ impl Expectation for TxInclusionExpectation { Err(broadcast::error::RecvError::Closed) => break, } } + tracing::debug!("tx inclusion capture task exiting"); }); self.capture_state = Some(CaptureState {