From 74fddd51ddbee3011ee8c3f1d15c99fc29db8005 Mon Sep 17 00:00:00 2001 From: andrussal Date: Thu, 11 Dec 2025 08:08:57 +0100 Subject: [PATCH] Improve workload and expectation logging --- .../src/expectations/consensus_liveness.rs | 14 +++++++---- .../workflows/src/workloads/da/expectation.rs | 24 +++++++++++++++++++ .../workflows/src/workloads/da/workload.rs | 5 +++- .../src/workloads/transaction/expectation.rs | 19 +++++++++++++++ .../src/workloads/transaction/workload.rs | 7 ++++++ 5 files changed, 63 insertions(+), 6 deletions(-) diff --git a/testing-framework/workflows/src/expectations/consensus_liveness.rs b/testing-framework/workflows/src/expectations/consensus_liveness.rs index 2d95dcc..77442fe 100644 --- a/testing-framework/workflows/src/expectations/consensus_liveness.rs +++ b/testing-framework/workflows/src/expectations/consensus_liveness.rs @@ -39,6 +39,7 @@ impl Expectation for ConsensusLiveness { async fn evaluate(&mut self, ctx: &RunContext) -> Result<(), DynError> { Self::ensure_participants(ctx)?; let target_hint = Self::target_blocks(ctx); + tracing::info!(target_hint, "consensus liveness: collecting samples"); let check = Self::collect_results(ctx).await; (*self).report(target_hint, check) } @@ -105,14 +106,13 @@ impl ConsensusLiveness { for attempt in 0..REQUEST_RETRIES { match Self::fetch_cluster_info(client).await { Ok((height, tip)) => { - samples.push(NodeSample { - label: format!("node-{idx}"), - height, - tip, - }); + let label = format!("node-{idx}"); + tracing::debug!(node = %label, height, tip = ?tip, attempt, "consensus_info collected"); + samples.push(NodeSample { label, height, tip }); break; } Err(err) if attempt + 1 == REQUEST_RETRIES => { + tracing::warn!(node = %format!("node-{idx}"), %err, "consensus_info failed after retries"); issues.push(ConsensusLivenessIssue::RequestFailed { node: format!("node-{idx}"), source: err, @@ -188,12 +188,16 @@ impl ConsensusLiveness { if check.issues.is_empty() { tracing::info!( target, + samples = check.samples.len(), heights = ?check.samples.iter().map(|s| s.height).collect::>(), tips = ?check.samples.iter().map(|s| s.tip).collect::>(), "consensus liveness expectation satisfied" ); Ok(()) } else { + for issue in &check.issues { + tracing::warn!(?issue, "consensus liveness issue"); + } Err(Box::new(ConsensusLivenessError::Violations { target, details: check.issues.into(), diff --git a/testing-framework/workflows/src/workloads/da/expectation.rs b/testing-framework/workflows/src/workloads/da/expectation.rs index 7af2e1d..4063549 100644 --- a/testing-framework/workflows/src/workloads/da/expectation.rs +++ b/testing-framework/workflows/src/workloads/da/expectation.rs @@ -58,6 +58,11 @@ impl Expectation for DaWorkloadExpectation { return Ok(()); } + tracing::info!( + planned_channels = self.planned_channels.len(), + "DA inclusion expectation starting capture" + ); + let planned = Arc::new( self.planned_channels .iter() @@ -113,6 +118,12 @@ impl Expectation for DaWorkloadExpectation { }; let required_inscriptions = minimum_required(planned_total, MIN_INCLUSION_RATIO); if planned_total.saturating_sub(missing_inscriptions.len()) < required_inscriptions { + tracing::warn!( + planned = planned_total, + missing = missing_inscriptions.len(), + required = required_inscriptions, + "DA expectation missing inscriptions" + ); return Err(DaExpectationError::MissingInscriptions { missing: missing_inscriptions, } @@ -125,12 +136,25 @@ impl Expectation for DaWorkloadExpectation { }; let required_blobs = minimum_required(planned_total, MIN_INCLUSION_RATIO); if planned_total.saturating_sub(missing_blobs.len()) < required_blobs { + tracing::warn!( + planned = planned_total, + missing = missing_blobs.len(), + required = required_blobs, + "DA expectation missing blobs" + ); return Err(DaExpectationError::MissingBlobs { missing: missing_blobs, } .into()); } + tracing::info!( + planned = planned_total, + inscriptions = planned_total - missing_inscriptions.len(), + blobs = planned_total - missing_blobs.len(), + "DA inclusion expectation satisfied" + ); + Ok(()) } } diff --git a/testing-framework/workflows/src/workloads/da/workload.rs b/testing-framework/workflows/src/workloads/da/workload.rs index 6af491e..e6d8b9b 100644 --- a/testing-framework/workflows/src/workloads/da/workload.rs +++ b/testing-framework/workflows/src/workloads/da/workload.rs @@ -179,7 +179,10 @@ async fn publish_blob( .await { Ok(blob_id) => return Ok(blob_id), - Err(err) => last_err = Some(err.into()), + Err(err) => { + tracing::debug!(attempt, executor = %executor.base_url(), %err, "DA: publish_blob failed"); + last_err = Some(err.into()) + } } } diff --git a/testing-framework/workflows/src/workloads/transaction/expectation.rs b/testing-framework/workflows/src/workloads/transaction/expectation.rs index 3c71164..5e32245 100644 --- a/testing-framework/workflows/src/workloads/transaction/expectation.rs +++ b/testing-framework/workflows/src/workloads/transaction/expectation.rs @@ -82,6 +82,13 @@ impl Expectation for TxInclusionExpectation { return Err(TxExpectationError::NoPlannedTransactions.into()); } + tracing::info!( + planned_txs = planned, + txs_per_block = self.txs_per_block.get(), + user_limit = self.user_limit.map(|u| u.get()), + "tx inclusion expectation starting capture" + ); + let wallet_pks = wallet_accounts .into_iter() .take(planned) @@ -137,8 +144,20 @@ impl Expectation for TxInclusionExpectation { let required = ((state.expected as f64) * MIN_INCLUSION_RATIO).ceil() as u64; if observed >= required { + tracing::info!( + observed, + required, + expected = state.expected, + "tx inclusion expectation satisfied" + ); Ok(()) } else { + tracing::warn!( + observed, + required, + expected = state.expected, + "tx inclusion expectation failed" + ); Err(TxExpectationError::InsufficientInclusions { observed, required }.into()) } } diff --git a/testing-framework/workflows/src/workloads/transaction/workload.rs b/testing-framework/workflows/src/workloads/transaction/workload.rs index 307b7b5..c03897c 100644 --- a/testing-framework/workflows/src/workloads/transaction/workload.rs +++ b/testing-framework/workflows/src/workloads/transaction/workload.rs @@ -162,6 +162,13 @@ impl<'a> Submission<'a> { .cloned() .collect::>(); + tracing::info!( + planned, + interval_ms = interval.as_millis(), + accounts_available = workload.accounts.len(), + "transaction workload submission plan" + ); + Ok(Self { plan, ctx,