From 93cff3265d2ae976b99e2a6d5c849ee64581a971 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Thu, 13 Aug 2026 08:53:42 +0000 Subject: [PATCH 01/14] refactor: add icp-events and report progress through it in four operations MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Progress reporting is what welds `crates/icp-cli/src/operations/` to the binary: six of those files import `crate::progress` and a seventh drives `indicatif` directly. This inverts the dependency so the rest of the crate split can proceed. New crate `crates/icp-events` expresses progress and user-facing notices as data: `Event`, `Reporter`, `Task`, `EventSink`, `CancelToken`. It depends only on serde and futures — not on `icp`, not on an async runtime, and on nothing terminal-shaped. `TaskKind` carries the three shapes the CLI uses today (spinner, multi-step with streamed command output, byte position) and `Event::Notice` carries the user-facing `info!`/`warn!`/`error!` output, so converting those later needs no redesign. `crates/icp-cli/src/events.rs` adds `IndicatifSink`, the one place that knows about both events and `indicatif`. It takes its styles and tick interval from `crate::progress` so the two renderers cannot drift while both exist. `install.rs`, `settings.rs`, `binding_env_vars.rs` and `candid_compat.rs` now take a `&Reporter` instead of `debug: bool`. `progress.rs` stays for `build.rs`, `sync.rs` and `snapshot_transfer.rs`, which a separate change owns. The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums `#[non_exhaustive]`, `TaskKind` closed. Events do not drive `--json`. --- .claude/CLAUDE.md | 1 + .claude/architecture.md | 26 + Cargo.lock | 10 + Cargo.toml | 1 + crates/icp-cli/Cargo.toml | 1 + crates/icp-cli/src/commands/deploy.rs | 9 +- crates/icp-cli/src/events.rs | 667 ++++++++++++++++++ crates/icp-cli/src/main.rs | 1 + .../src/operations/binding_env_vars.rs | 138 +++- .../icp-cli/src/operations/candid_compat.rs | 117 ++- crates/icp-cli/src/operations/install.rs | 144 +++- crates/icp-cli/src/operations/mod.rs | 3 + crates/icp-cli/src/operations/settings.rs | 122 +++- crates/icp-cli/src/operations/test_support.rs | 98 +++ crates/icp-cli/src/progress.rs | 33 +- crates/icp-events/Cargo.toml | 23 + crates/icp-events/src/cancel.rs | 173 +++++ crates/icp-events/src/event.rs | 229 ++++++ crates/icp-events/src/lib.rs | 57 ++ crates/icp-events/src/reporter.rs | 588 +++++++++++++++ crates/icp-events/src/sink.rs | 134 ++++ 21 files changed, 2506 insertions(+), 69 deletions(-) create mode 100644 crates/icp-cli/src/events.rs create mode 100644 crates/icp-cli/src/operations/test_support.rs create mode 100644 crates/icp-events/Cargo.toml create mode 100644 crates/icp-events/src/cancel.rs create mode 100644 crates/icp-events/src/event.rs create mode 100644 crates/icp-events/src/lib.rs create mode 100644 crates/icp-events/src/reporter.rs create mode 100644 crates/icp-events/src/sink.rs diff --git a/.claude/CLAUDE.md b/.claude/CLAUDE.md index edb1cec9b..7bcdd8150 100644 --- a/.claude/CLAUDE.md +++ b/.claude/CLAUDE.md @@ -23,6 +23,7 @@ cargo fmt && cargo clippy # Run after changes pass tests - **`crates/icp-cli`**: Main CLI binary (`icp`) with command implementations - **`crates/icp`**: Core library with project model, manifest loading, canister management, network configuration - **`crates/icp-canister-interfaces`**: Canister interface definitions for ICP system canisters +- **`crates/icp-events`**: Progress and user-facing notices as data (`Event`, `Reporter`, `Task`, `EventSink`), so operations can report without depending on the terminal. serde + futures only - **`crates/schema-gen`**: JSON schema generation for manifest validation ### Command Structure diff --git a/.claude/architecture.md b/.claude/architecture.md index 9f3a45690..9096a33a8 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -77,6 +77,32 @@ These constants are defined in `crates/icp/src/prelude.rs` as `LOCAL` and `IC` a Store management is in `crates/icp/src/store_id.rs`. +## Progress & User-Facing Output + +Operations in `crates/icp-cli/src/operations/` report progress as data, not as terminal +calls. `crates/icp-events` defines the vocabulary (`Event`, `Reporter`, `Task`, +`EventSink`, `CancelToken`) and depends only on serde and futures — never on `icp`, an +async runtime, or anything terminal-shaped. `crates/icp-cli/src/events.rs` holds +`IndicatifSink`, the only place that maps events onto `indicatif` bars. + +- New or converted operations take a `&Reporter`, never a `debug: bool` and never + `crate::progress` directly. Callers build one per operation with + `events::indicatif_reporter(ctx.debug)`. +- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer, kept only while + `build.rs`, `sync.rs`, and `snapshot_transfer.rs` still use it. Do not add users. +- The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums + `#[non_exhaustive]`, `TaskKind` closed. +- Events do not drive `--json`. `--json` means the command's final result; progress never + appears in it. +- `tracing` at INFO level is product output here, not logging — `logging.rs` installs a + `UserLayer` that prints `Level::INFO` to stderr unprefixed. `Event::Notice` is the event + model's equivalent; the `info!`/`warn!`/`error!` calls inside `operations/` have not been + converted yet. + +Operations are unit-tested by running them against `RecordingSink` and asserting on the +resulting `Vec`; see `operations/test_support.rs`. `events.rs` additionally compares +`IndicatifSink`'s rendered frames against `ProgressManager`'s to catch output regressions. + ## Telemetry Anonymous usage telemetry implementation. User-facing documentation is in `docs/telemetry.md`. diff --git a/Cargo.lock b/Cargo.lock index 1d9ca596b..8b8e22736 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3726,6 +3726,7 @@ dependencies = [ "ic-utils", "icp", "icp-canister-interfaces", + "icp-events", "icrc-ledger-types", "indicatif", "indoc", @@ -3769,6 +3770,15 @@ dependencies = [ "wslpath2", ] +[[package]] +name = "icp-events" +version = "0.1.0" +dependencies = [ + "futures", + "serde", + "serde_json", +] + [[package]] name = "icp-sync-plugin" version = "1.3.0" diff --git a/Cargo.toml b/Cargo.toml index ced350649..27b98e4f5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -60,6 +60,7 @@ ic-management-canister-types = { version = "0.8.0" } ic-utils = { version = "0.49.1" } icp = { path = "crates/icp" } icp-canister-interfaces = { path = "crates/icp-canister-interfaces" } +icp-events = { path = "crates/icp-events" } icp-sync-plugin = { path = "crates/icp-sync-plugin" } ic-identity-hsm = "0.49.1" icrc-ledger-types = "0.1.10" diff --git a/crates/icp-cli/Cargo.toml b/crates/icp-cli/Cargo.toml index 5ad3e0f0b..9bf6fae7b 100644 --- a/crates/icp-cli/Cargo.toml +++ b/crates/icp-cli/Cargo.toml @@ -43,6 +43,7 @@ ic-ledger-types.workspace = true ic-management-canister-types.workspace = true ic-utils.workspace = true icp-canister-interfaces.workspace = true +icp-events.workspace = true icp = { workspace = true, features = ["clap"] } icrc-ledger-types.workspace = true indicatif.workspace = true diff --git a/crates/icp-cli/src/commands/deploy.rs b/crates/icp-cli/src/commands/deploy.rs index b2a1fe4ca..0f38bafa8 100644 --- a/crates/icp-cli/src/commands/deploy.rs +++ b/crates/icp-cli/src/commands/deploy.rs @@ -21,6 +21,7 @@ use tracing::info; use crate::options::EnvironmentOpt; use crate::{ commands::{args::ArgsOpt, canister::create}, + events::indicatif_reporter, operations::{ binding_env_vars::set_binding_env_vars_many, build::build_many_with_progress_bar, @@ -325,7 +326,7 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: &env.name, target_canisters.clone(), canister_list.clone(), - ctx.debug, + &indicatif_reporter(ctx.debug), ) .await .map_err(|e| anyhow!(e))?; @@ -335,7 +336,7 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: args.proxy, target_canisters, canister_list, - ctx.debug, + &indicatif_reporter(ctx.debug), ) .await .map_err(|e| anyhow!(e))?; @@ -385,7 +386,7 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: .iter() .map(|(name, cid, mode, _, _)| (&**name, *cid, *mode)), ctx.artifacts.clone(), - ctx.debug, + &indicatif_reporter(ctx.debug), ) .await .map_err(|e| anyhow!(e))?; @@ -398,7 +399,7 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: args.proxy, canisters, ctx.artifacts.clone(), - ctx.debug, + &indicatif_reporter(ctx.debug), ) .await?; diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs new file mode 100644 index 000000000..211df24fa --- /dev/null +++ b/crates/icp-cli/src/events.rs @@ -0,0 +1,667 @@ +//! Rendering [`icp_events`] onto the terminal. +//! +//! [`IndicatifSink`] is the only place that knows both about events and about +//! `indicatif`. Operations emit events; this turns them into the same progress bars +//! the CLI has always drawn. The styles come from [`crate::progress`] so the two +//! renderers cannot drift apart while both exist. + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; + +use icp_events::{Event, EventSink, Outcome, Reporter, TaskId, TaskKind}; +use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget, ProgressStyle}; +use itertools::Itertools; +use tracing::debug; + +use crate::progress::{RollingLines, STEADY_TICK, failure_style, running_style, success_style}; + +/// How many lines of a step's output stay on screen while it runs. +const VISIBLE_STEP_LINES: usize = 4; + +/// A [`Reporter`] that draws to the terminal. +/// +/// Each call site gets its own reporter — and so its own [`MultiProgress`] — which +/// matches how `ProgressManager` was used: bars belonging to one operation are +/// grouped, and the group is torn down when the operation returns. +pub(crate) fn indicatif_reporter(hidden: bool) -> Reporter { + Reporter::new(Arc::new(IndicatifSink::new(hidden))) +} + +/// Renders [`Event`]s as `indicatif` progress bars. +pub(crate) struct IndicatifSink { + multi: MultiProgress, + bars: Mutex>, +} + +// `indicatif::ProgressBar` is not `Debug`, so neither derive nor a useful dump of +// the bars is available; report which tasks are still live instead. +impl std::fmt::Debug for IndicatifSink { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + let live: Vec = match self.bars.lock() { + Ok(bars) => bars.keys().copied().sorted().collect(), + Err(_) => Vec::new(), + }; + + f.debug_struct("IndicatifSink") + .field("live", &live) + .finish() + } +} + +/// Everything needed to keep drawing one task. +struct BarState { + bar: ProgressBar, + /// Byte bars carry their own template, so they do not take the spinner's + /// success/failure styles when they finish. + styled_spinner: bool, + /// Title of the step in progress, if any. + step_title: Option, + /// The tail of the step's output that is currently on screen. + visible: RollingLines, +} + +impl IndicatifSink { + /// Draw to stderr, or nowhere at all when `hidden` (that is, under `--debug`, + /// where bars would fight with the log output). + pub(crate) fn new(hidden: bool) -> Self { + Self::with_draw_target(if hidden { + ProgressDrawTarget::hidden() + } else { + // What `MultiProgress::new` picks anyway; spelled out so both branches + // go through one constructor. + ProgressDrawTarget::stderr() + }) + } + + fn with_draw_target(target: ProgressDrawTarget) -> Self { + let multi = MultiProgress::with_draw_target(target); + + Self { + multi, + bars: Mutex::new(HashMap::new()), + } + } + + fn start(&self, id: TaskId, kind: TaskKind, label: Option) { + let state = match kind { + TaskKind::Bytes { total } => { + let bar = self.multi.add(ProgressBar::new(total)); + bar.set_style(byte_style()); + // Byte bars label themselves undecorated; spinners wrap the name in + // brackets. Both match what the code being replaced did. + if let Some(label) = label { + bar.set_prefix(label); + } + + BarState { + bar, + styled_spinner: false, + step_title: None, + visible: RollingLines::new(VISIBLE_STEP_LINES), + } + } + // Spinners and multi-step bars are the same bar; only the message + // differs, and steps build a richer one. + _ => { + let bar = self + .multi + .add(ProgressBar::new_spinner().with_style(running_style())); + bar.enable_steady_tick(STEADY_TICK); + if let Some(label) = label { + bar.set_prefix(format!("[{label}]")); + } + + BarState { + bar, + styled_spinner: true, + step_title: None, + visible: RollingLines::new(VISIBLE_STEP_LINES), + } + } + }; + + self.bars.lock().expect("bars poisoned").insert(id, state); + } + + fn finish(&self, id: TaskId, outcome: Outcome, message: Option) { + let Some(state) = self.bars.lock().expect("bars poisoned").remove(&id) else { + return; + }; + + // A neutral finish leaves the style alone, and byte bars never take the + // spinner styles at all. + let style = match outcome { + Outcome::Success if state.styled_spinner => Some(success_style()), + Outcome::Failure if state.styled_spinner => Some(failure_style()), + _ => None, + }; + + // Each arm makes the same sequence of calls the code being replaced made, so + // that the intermediate redraws match too and not just the final frame. + match (style, message) { + (Some(style), message) => { + state.bar.set_style(style); + if let Some(message) = message { + state.bar.set_message(message); + } + state.bar.finish(); + } + (None, Some(message)) => state.bar.finish_with_message(message), + (None, None) => state.bar.finish(), + } + } + + /// Redraw the step in progress: its title, then the tail of its output. + fn redraw_step(state: &BarState) { + let Some(title) = &state.step_title else { + return; + }; + + // Make the output + // │ look prettier... + // └ + let lines = state.visible.iter().map(|s| format!("│ {s}")).join("\n"); + state.bar.set_message(format!("{title}\n{lines}\n└\n\n")); + } +} + +impl EventSink for IndicatifSink { + fn emit(&self, event: Event) { + match event { + Event::TaskStarted { id, kind, label } => self.start(id, kind, label), + + Event::TaskMessage { id, message } => { + if let Some(state) = self.bars.lock().expect("bars poisoned").get(&id) { + state.bar.set_message(message); + } + } + + Event::TaskPosition { id, position } => { + if let Some(state) = self.bars.lock().expect("bars poisoned").get(&id) { + state.bar.set_position(position); + } + } + + Event::StepStarted { id, title, .. } => { + if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { + state.step_title = Some(title); + state.visible = RollingLines::new(VISIBLE_STEP_LINES); + } + } + + Event::StepOutput { id, line } => { + debug!("{line}"); + + if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { + state.visible.push(line); + Self::redraw_step(state); + } + } + + Event::StepFinished { id, .. } => { + if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { + state.step_title = None; + } + } + + Event::TaskFinished { + id, + outcome, + message, + } => self.finish(id, outcome, message), + + // User-facing notices go through `tracing`, which the CLI's `UserLayer` + // prints as product output. Converting the operations' `info!`/`warn!`/ + // `error!` calls to notices is a separate work item; this arm is what + // will receive them. + Event::Notice { level, message } => match level { + icp_events::NoticeLevel::Warn => tracing::warn!("{message}"), + icp_events::NoticeLevel::Error => tracing::error!("{message}"), + _ => tracing::info!("{message}"), + }, + + _ => {} + } + } +} + +/// The template byte-transfer bars use. +fn byte_style() -> ProgressStyle { + ProgressStyle::default_bar() + .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") + .expect("invalid progress bar template") + .progress_chars("#>-") +} + +/// Proof that the events path draws what `ProgressManager` drew. +/// +/// Both renderers are pointed at the same recording terminal and driven through the +/// same logical sequence; the frames they emit are then compared byte for byte. This +/// is what backs the claim that converting the four operations left the visible CLI +/// output unchanged. +#[cfg(test)] +mod rendering_equivalence { + use super::*; + use crate::progress::{ProgressManager, ProgressManagerSettings}; + use futures::executor::block_on; + use indicatif::TermLike; + use std::io; + + /// A terminal that remembers what was written to it. + #[derive(Debug, Clone, Default)] + struct RecordingTerm { + writes: Arc>>, + } + + /// The spinner's animation glyphs, which advance on a timer and so cannot be + /// compared directly between two runs. + const ANIMATION_GLYPHS: [char; 5] = ['✶', '✸', '✹', '✺', '✷']; + + impl RecordingTerm { + /// Every frame drawn, with the spinner's animation collapsed to a single + /// marker and the resulting consecutive duplicates removed. + /// + /// What survives is the sequence of *states* a bar passed through — prefix, + /// message, and final tick — which is exactly what has to match. Two things are + /// dropped on the way: the blank line indicatif writes to pad out the rest of + /// the terminal row, which is a function of the frame it follows, and the + /// animation glyph, which advances on a timer and so differs run to run. + fn frames(&self) -> Vec { + let mut frames: Vec = self + .writes + .lock() + .expect("writes poisoned") + .iter() + .filter(|frame| !frame.trim().is_empty()) + .map(|frame| { + frame + .chars() + .map(|c| { + if ANIMATION_GLYPHS.contains(&c) { + '~' + } else { + c + } + }) + .collect() + }) + .collect(); + frames.dedup(); + frames + } + } + + impl TermLike for RecordingTerm { + fn width(&self) -> u16 { + 80 + } + + fn move_cursor_up(&self, _n: usize) -> io::Result<()> { + Ok(()) + } + + fn move_cursor_down(&self, _n: usize) -> io::Result<()> { + Ok(()) + } + + fn move_cursor_right(&self, _n: usize) -> io::Result<()> { + Ok(()) + } + + fn move_cursor_left(&self, _n: usize) -> io::Result<()> { + Ok(()) + } + + fn write_line(&self, s: &str) -> io::Result<()> { + self.writes + .lock() + .expect("writes poisoned") + .push(s.to_string()); + Ok(()) + } + + fn write_str(&self, s: &str) -> io::Result<()> { + self.writes + .lock() + .expect("writes poisoned") + .push(s.to_string()); + Ok(()) + } + + fn clear_line(&self) -> io::Result<()> { + Ok(()) + } + + fn flush(&self) -> io::Result<()> { + Ok(()) + } + } + + fn recording_target(term: &RecordingTerm) -> ProgressDrawTarget { + ProgressDrawTarget::term_like(Box::new(term.clone())) + } + + fn old_manager(term: &RecordingTerm) -> ProgressManager { + let manager = ProgressManager::new(ProgressManagerSettings { hidden: false }); + manager + .multi_progress + .set_draw_target(recording_target(term)); + manager + } + + fn new_reporter(term: &RecordingTerm) -> Reporter { + Reporter::new(Arc::new(IndicatifSink::with_draw_target(recording_target( + term, + )))) + } + + /// Every frame `ProgressManager` drew for one canister's outcome. + fn old_frames( + result: Result<(), E>, + success: &str, + error: impl Fn(&E) -> String, + ) -> Vec { + let term = RecordingTerm::default(); + let manager = old_manager(&term); + + let bar = manager.create_progress_bar("backend"); + bar.set_message("Installing..."); + let _ = block_on(ProgressManager::execute_with_progress( + &bar, + async { result }, + || success.to_string(), + error, + )); + + term.frames() + } + + /// Every frame the event stream draws for the same outcome. + fn new_frames( + result: Result<(), E>, + success: &str, + error: impl Fn(&E) -> String, + ) -> Vec { + let term = RecordingTerm::default(); + let reporter = new_reporter(&term); + + let task = reporter.task(TaskKind::Spinner, "backend"); + task.message("Installing..."); + let _ = block_on(task.run(async { result }, || success.to_string(), error)); + + term.frames() + } + + #[test] + fn a_success_draws_the_same_frames_as_before() { + let old = old_frames::(Ok(()), "Installed successfully", |e| e.clone()); + let new = new_frames::(Ok(()), "Installed successfully", |e| e.clone()); + + assert!( + old.iter().any(|f| f.contains("Installed successfully")), + "old frames: {old:?}" + ); + assert_eq!(old, new); + } + + #[test] + fn a_failure_draws_the_same_frames_as_before() { + let message = "Failed to install canister: boom"; + let old = old_frames(Err("boom".to_string()), "unused", |_| message.to_string()); + let new = new_frames(Err("boom".to_string()), "unused", |_| message.to_string()); + + assert!( + old.iter().any(|f| f.contains(message)), + "old frames: {old:?}" + ); + assert_eq!(old, new); + } + + /// `candid_compat` skipped a canister with `finish_with_message`, which left the + /// running style in place and drew a single frame. A neutral finish has to do the + /// same, down to not slipping in an extra redraw. + #[test] + fn a_skip_draws_the_same_frames_as_finish_with_message() { + let term = RecordingTerm::default(); + old_manager(&term) + .create_progress_bar("backend") + .finish_with_message("Skipped (not an upgrade)"); + let old = term.frames(); + + let term = RecordingTerm::default(); + new_reporter(&term) + .task(TaskKind::Spinner, "backend") + .skip("Skipped (not an upgrade)"); + let new = term.frames(); + + assert!( + old.iter().any(|f| f.contains("Skipped (not an upgrade)")), + "old frames: {old:?}" + ); + assert_eq!(old, new); + } + + /// Several canisters share one `MultiProgress`, so their bars have to be added in + /// the same order to land on the same lines. + #[test] + fn bars_are_drawn_in_the_order_the_canisters_were_given() { + let term = RecordingTerm::default(); + let manager = old_manager(&term); + for name in ["frontend", "backend"] { + manager + .create_progress_bar(name) + .finish_with_message("done"); + } + let old = term.frames(); + + let term = RecordingTerm::default(); + let reporter = new_reporter(&term); + for name in ["frontend", "backend"] { + reporter.task(TaskKind::Spinner, name).skip("done"); + } + let new = term.frames(); + + assert!(!old.is_empty()); + assert_eq!(old, new); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Hidden bars still track state, so the sink can be exercised without a tty. + fn sink() -> IndicatifSink { + IndicatifSink::new(true) + } + + fn live_bars(sink: &IndicatifSink) -> usize { + sink.bars.lock().unwrap().len() + } + + #[test] + fn a_spinner_lives_from_start_to_finish() { + let sink = sink(); + + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }); + assert_eq!(live_bars(&sink), 1); + + sink.emit(Event::TaskMessage { + id: TaskId(0), + message: "Installing...".into(), + }); + sink.emit(Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Installed successfully".into()), + }); + + assert_eq!(live_bars(&sink), 0); + } + + #[test] + fn a_label_becomes_a_bracketed_prefix() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }); + + let bars = sink.bars.lock().unwrap(); + assert_eq!(bars[&TaskId(0)].bar.prefix(), "[backend]"); + } + + #[test] + fn byte_bars_take_their_label_undecorated_and_track_position() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Bytes { total: 100 }, + label: Some("upload".into()), + }); + sink.emit(Event::TaskPosition { + id: TaskId(0), + position: 64, + }); + + let bars = sink.bars.lock().unwrap(); + let state = &bars[&TaskId(0)]; + assert_eq!(state.bar.prefix(), "upload"); + assert_eq!(state.bar.position(), 64); + assert_eq!(state.bar.length(), Some(100)); + assert!(!state.styled_spinner); + } + + #[test] + fn step_output_is_framed_like_the_progress_manager_did() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Build".into(), + }, + label: Some("backend".into()), + }); + sink.emit(Event::StepStarted { + id: TaskId(0), + index: 0, + title: "Building: step 1 of 1 cargo build".into(), + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "compiling".into(), + }); + + let bars = sink.bars.lock().unwrap(); + assert_eq!( + bars[&TaskId(0)].bar.message(), + "Building: step 1 of 1 cargo build\n│ compiling\n└\n\n" + ); + } + + #[test] + fn only_the_last_few_output_lines_stay_on_screen() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Build".into(), + }, + label: None, + }); + sink.emit(Event::StepStarted { + id: TaskId(0), + index: 0, + title: "t".into(), + }); + for i in 0..VISIBLE_STEP_LINES + 2 { + sink.emit(Event::StepOutput { + id: TaskId(0), + line: format!("line {i}"), + }); + } + + let bars = sink.bars.lock().unwrap(); + assert_eq!( + bars[&TaskId(0)].bar.message(), + "t\n│ line 2\n│ line 3\n│ line 4\n│ line 5\n└\n\n" + ); + } + + #[test] + fn a_new_step_starts_from_an_empty_screen() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Build".into(), + }, + label: None, + }); + sink.emit(Event::StepStarted { + id: TaskId(0), + index: 0, + title: "first".into(), + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "old".into(), + }); + sink.emit(Event::StepFinished { + id: TaskId(0), + index: 0, + }); + sink.emit(Event::StepStarted { + id: TaskId(0), + index: 1, + title: "second".into(), + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "new".into(), + }); + + let bars = sink.bars.lock().unwrap(); + assert_eq!(bars[&TaskId(0)].bar.message(), "second\n│ new\n└\n\n"); + } + + #[test] + fn a_neutral_finish_keeps_its_message() { + let sink = sink(); + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }); + sink.emit(Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Neutral, + message: Some("Skipped (not an upgrade)".into()), + }); + + assert_eq!(live_bars(&sink), 0); + } + + #[test] + fn events_for_an_unknown_task_are_ignored() { + let sink = sink(); + + // Finishing twice, or reporting after a finish, must not panic. + sink.emit(Event::TaskMessage { + id: TaskId(99), + message: "nobody home".into(), + }); + sink.emit(Event::TaskFinished { + id: TaskId(99), + outcome: Outcome::Failure, + message: None, + }); + } +} diff --git a/crates/icp-cli/src/main.rs b/crates/icp-cli/src/main.rs index 6fe636038..dea176d80 100644 --- a/crates/icp-cli/src/main.rs +++ b/crates/icp-cli/src/main.rs @@ -17,6 +17,7 @@ mod artifacts; mod commands; mod complete; mod dist; +mod events; mod logging; pub(crate) mod operations; mod options; diff --git a/crates/icp-cli/src/operations/binding_env_vars.rs b/crates/icp-cli/src/operations/binding_env_vars.rs index a2118f193..676bba5be 100644 --- a/crates/icp-cli/src/operations/binding_env_vars.rs +++ b/crates/icp-cli/src/operations/binding_env_vars.rs @@ -7,7 +7,7 @@ use icp::Canister; use snafu::Snafu; use tracing::error; -use crate::progress::{ProgressManager, ProgressManagerSettings}; +use icp_events::{Reporter, TaskKind}; use super::proxy::UpdateOrProxyError; use super::proxy_management; @@ -84,7 +84,7 @@ pub(crate) async fn set_binding_env_vars_many( environment_name: &str, target_canisters: Vec<(Principal, Canister)>, canister_list: BTreeMap, - debug: bool, + reporter: &Reporter, ) -> Result<(), SetBindingEnvVarsManyError> { // Check that all the canisters in this environment have an id // We need to have all the ids to generate environment variables @@ -117,10 +117,11 @@ pub(crate) async fn set_binding_env_vars_many( } let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: debug }); for (cid, info) in target_canisters { - let pb = progress_manager.create_progress_bar(&info.name); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let task = reporter.task(TaskKind::Spinner, info.name.as_str()); let canister_name = info.name.clone(); // Each canister receives only the ids it is wired to (its own project's @@ -143,22 +144,20 @@ pub(crate) async fn set_binding_env_vars_many( let settings_fn = { let agent = agent.clone(); - let pb = pb.clone(); - async move { - pb.set_message("Updating environment variables..."); - set_env_vars_for_canister(&agent, proxy, &cid, &info, &binding_vars).await - } + async move { set_env_vars_for_canister(&agent, proxy, &cid, &info, &binding_vars).await } }; futs.push_back(async move { - let result = ProgressManager::execute_with_progress( - &pb, - settings_fn, - || "Environment variables updated successfully".to_string(), - |err| format!("Failed to update environment variables: {err}"), - ) - .await; + task.message("Updating environment variables..."); + + let result = task + .run( + settings_fn, + || "Environment variables updated successfully".to_string(), + |err| format!("Failed to update environment variables: {err}"), + ) + .await; // Map error to include canister context for deferred printing result.map_err(|error| BindingEnvVarsFailure { @@ -198,3 +197,110 @@ pub(crate) async fn set_binding_env_vars_many( Ok(()) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{ + bare_canister, outcome_of, recording_reporter, task_labels, unreachable_agent, + }; + use icp_events::{Event, Outcome, TaskId, TaskKind}; + + fn canister_id() -> Principal { + Principal::from_text("ryjl3-tyaaa-aaaaa-aaaba-cai").unwrap() + } + + fn ids(names: &[&str]) -> BTreeMap { + names + .iter() + .map(|name| (name.to_string(), canister_id())) + .collect() + } + + /// The agent cannot be reached, so this pins the reporting shape — start, + /// message, failure verdict — rather than the wording of the transport error. + #[tokio::test] + async fn an_unreachable_canister_is_reported_as_a_failure() { + let (reporter, sink) = recording_reporter(); + + let result = set_binding_env_vars_many( + unreachable_agent(), + None, + "default", + vec![(canister_id(), bare_canister("backend"))], + ids(&["backend"]), + &reporter, + ) + .await; + + assert!(result.is_err()); + + let events = sink.events(); + assert_eq!( + events[..2], + [ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskMessage { + id: TaskId(0), + message: "Updating environment variables...".into(), + }, + ] + ); + + let (outcome, message) = outcome_of(&events, TaskId(0)); + assert_eq!(outcome, Outcome::Failure); + assert!( + message + .as_deref() + .is_some_and(|m| m.starts_with("Failed to update environment variables: ")), + "unexpected message: {message:?}" + ); + } + + #[tokio::test] + async fn one_task_per_canister_in_the_given_order() { + let (reporter, sink) = recording_reporter(); + + let _ = set_binding_env_vars_many( + unreachable_agent(), + None, + "default", + vec![ + (canister_id(), bare_canister("frontend")), + (canister_id(), bare_canister("backend")), + ], + ids(&["frontend", "backend"]), + &reporter, + ) + .await; + + assert_eq!( + task_labels(&sink.events()), + vec![Some("frontend".to_string()), Some("backend".to_string())] + ); + } + + /// Canisters without ids are rejected before any work starts, so there is + /// nothing to report progress about. + #[tokio::test] + async fn a_canister_without_an_id_aborts_before_any_task_starts() { + let (reporter, sink) = recording_reporter(); + + let result = set_binding_env_vars_many( + unreachable_agent(), + None, + "default", + vec![(canister_id(), bare_canister("backend"))], + ids(&[]), + &reporter, + ) + .await; + + assert!(result.is_err()); + assert!(sink.events().is_empty()); + } +} diff --git a/crates/icp-cli/src/operations/candid_compat.rs b/crates/icp-cli/src/operations/candid_compat.rs index 07355a012..9181d2560 100644 --- a/crates/icp-cli/src/operations/candid_compat.rs +++ b/crates/icp-cli/src/operations/candid_compat.rs @@ -11,10 +11,9 @@ use ic_management_canister_types::CanisterInstallMode; use snafu::Snafu; use tracing::{debug, error}; -use crate::{ - operations::{misc::fetch_canister_metadata, wasm::extract_candid_service}, - progress::{ProgressManager, ProgressManagerSettings}, -}; +use icp_events::{Reporter, TaskKind}; + +use crate::operations::{misc::fetch_canister_metadata, wasm::extract_candid_service}; /// Checks Candid interface compatibility for all canisters that would be /// upgraded. Aborts if any canister has an incompatible interface. @@ -22,27 +21,27 @@ pub(crate) async fn check_candid_compatibility_many( agent: Agent, canisters: impl IntoIterator, artifacts: Arc, - debug: bool, + reporter: &Reporter, ) -> Result<(), CandidCheckManyError> { let mut check_futs = FuturesOrdered::new(); - let check_progress = ProgressManager::new(ProgressManagerSettings { hidden: debug }); for (name, cid, mode) in canisters { - let pb = check_progress.create_progress_bar(name); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let task = reporter.task(TaskKind::Spinner, name); let is_upgrade = matches!(mode, CanisterInstallMode::Upgrade(_)); let agent = agent.clone(); let artifacts = artifacts.clone(); check_futs.push_back(async move { if !is_upgrade { - pb.finish_with_message("Skipped (not an upgrade)"); + task.skip("Skipped (not an upgrade)"); return Ok::<_, CandidCheckFailure>(()); } - pb.set_message("Checking compatibility..."); + task.message("Checking compatibility..."); - ProgressManager::execute_with_progress( - &pb, + task.run( check_canister_candid_compat(&agent, &cid, name, &*artifacts), || "Compatible".to_string(), |_| "Incompatible".to_string(), @@ -206,3 +205,99 @@ pub(crate) enum CandidCompatibility { pub struct CandidCheckManyError { names: Vec, } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{ + EmptyArtifacts, outcome_of, recording_reporter, task_labels, unreachable_agent, + }; + use icp_events::{Event, Outcome, TaskId, TaskKind}; + + fn canister_id() -> Principal { + Principal::from_text("ryjl3-tyaaa-aaaaa-aaaba-cai").unwrap() + } + + /// A fresh install has no deployed interface to be compatible with, so the check + /// is skipped — and a skip is neither a success nor a failure. + #[tokio::test] + async fn a_non_upgrade_is_skipped_without_a_verdict() { + let (reporter, sink) = recording_reporter(); + + let result = check_candid_compatibility_many( + unreachable_agent(), + vec![("backend", canister_id(), CanisterInstallMode::Install)], + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + assert!(result.is_ok()); + assert_eq!( + sink.events(), + vec![ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Neutral, + message: Some("Skipped (not an upgrade)".into()), + }, + ] + ); + } + + /// A missing artifact cannot be checked, so the upgrade is waved through and the + /// install path reports the missing artifact instead. + #[tokio::test] + async fn an_upgrade_with_no_artifact_is_reported_compatible() { + let (reporter, sink) = recording_reporter(); + + let result = check_candid_compatibility_many( + unreachable_agent(), + vec![("backend", canister_id(), CanisterInstallMode::Upgrade(None))], + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + assert!(result.is_ok()); + let events = sink.events(); + assert_eq!( + events[1], + Event::TaskMessage { + id: TaskId(0), + message: "Checking compatibility...".into(), + } + ); + assert_eq!( + outcome_of(&events, TaskId(0)), + (Outcome::Success, Some("Compatible".to_string())) + ); + } + + #[tokio::test] + async fn each_canister_gets_its_own_task_in_order() { + let (reporter, sink) = recording_reporter(); + + let result = check_candid_compatibility_many( + unreachable_agent(), + vec![ + ("frontend", canister_id(), CanisterInstallMode::Install), + ("backend", canister_id(), CanisterInstallMode::Install), + ], + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + assert!(result.is_ok()); + assert_eq!( + task_labels(&sink.events()), + vec![Some("frontend".to_string()), Some("backend".to_string())] + ); + } +} diff --git a/crates/icp-cli/src/operations/install.rs b/crates/icp-cli/src/operations/install.rs index 24f90fd4e..eab971b1a 100644 --- a/crates/icp-cli/src/operations/install.rs +++ b/crates/icp-cli/src/operations/install.rs @@ -11,7 +11,7 @@ use snafu::{ResultExt, Snafu}; use std::sync::Arc; use tracing::{debug, error, warn}; -use crate::progress::{ProgressManager, ProgressManagerSettings}; +use icp_events::{Reporter, TaskKind}; use super::misc::fetch_canister_metadata; use super::proxy::UpdateOrProxyError; @@ -349,7 +349,7 @@ async fn stop_and_start_if_upgrade( install_result } -/// Installs code to multiple canisters and displays progress bars. +/// Installs code to multiple canisters, reporting progress per canister. pub(crate) async fn install_many( agent: Agent, proxy: Option, @@ -363,22 +363,20 @@ pub(crate) async fn install_many( ), >, artifacts: Arc, - debug: bool, + reporter: &Reporter, ) -> Result<(), InstallManyError> { let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: debug }); for (name, cid, mode, status, init_args) in canisters { - let pb = progress_manager.create_progress_bar(&name); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let task = reporter.task(TaskKind::Spinner, name.as_str()); let agent = agent.clone(); let install_fn = { - let pb = pb.clone(); let artifacts = artifacts.clone(); let name = name.clone(); async move { - pb.set_message("Installing..."); - let wasm = artifacts.lookup(&name).await.map_err(|_| { InstallOperationError::ArtifactNotFound { canister_name: name.clone(), @@ -401,13 +399,15 @@ pub(crate) async fn install_many( }; futs.push_back(async move { - let result = ProgressManager::execute_with_progress( - &pb, - install_fn, - || "Installed successfully".to_string(), - |err| format!("Failed to install canister: {err}"), - ) - .await; + task.message("Installing..."); + + let result = task + .run( + install_fn, + || "Installed successfully".to_string(), + |err| format!("Failed to install canister: {err}"), + ) + .await; result.map_err(|error| InstallFailure { canister_name: name.clone(), @@ -444,3 +444,117 @@ pub(crate) async fn install_many( Ok(()) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{ + EmptyArtifacts, outcome_of, recording_reporter, task_labels, unreachable_agent, + }; + use icp_events::{Event, Outcome, TaskId, TaskKind}; + + fn canister_id() -> Principal { + Principal::from_text("ryjl3-tyaaa-aaaaa-aaaba-cai").unwrap() + } + + /// A missing build artifact is caught before the agent is touched, so this + /// exercises the whole reporting path without a network. + #[tokio::test] + async fn a_missing_artifact_is_reported_against_its_canister() { + let (reporter, sink) = recording_reporter(); + + let result = install_many( + unreachable_agent(), + None, + vec![( + "backend".to_string(), + canister_id(), + CanisterInstallMode::Install, + CanisterStatusType::Stopped, + None, + )], + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + assert!(result.is_err()); + assert_eq!( + sink.events(), + vec![ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskMessage { + id: TaskId(0), + message: "Installing...".into(), + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Failure, + message: Some( + "Failed to install canister: Could not find build artifact for canister \ + 'backend'" + .into() + ), + }, + ] + ); + } + + #[tokio::test] + async fn one_task_per_canister_in_the_given_order() { + let (reporter, sink) = recording_reporter(); + + let canisters = ["frontend", "backend", "database"].map(|name| { + ( + name.to_string(), + canister_id(), + CanisterInstallMode::Install, + CanisterStatusType::Stopped, + None, + ) + }); + + let _ = install_many( + unreachable_agent(), + None, + canisters, + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + let events = sink.events(); + assert_eq!( + task_labels(&events), + vec![ + Some("frontend".to_string()), + Some("backend".to_string()), + Some("database".to_string()), + ] + ); + for id in 0..3 { + assert_eq!(outcome_of(&events, TaskId(id)).0, Outcome::Failure); + } + } + + #[tokio::test] + async fn nothing_to_install_reports_nothing() { + let (reporter, sink) = recording_reporter(); + + let result = install_many( + unreachable_agent(), + None, + Vec::new(), + Arc::new(EmptyArtifacts), + &reporter, + ) + .await; + + assert!(result.is_ok()); + assert!(sink.events().is_empty()); + } +} diff --git a/crates/icp-cli/src/operations/mod.rs b/crates/icp-cli/src/operations/mod.rs index 5ce6546d0..4a1bd66ab 100644 --- a/crates/icp-cli/src/operations/mod.rs +++ b/crates/icp-cli/src/operations/mod.rs @@ -15,3 +15,6 @@ pub(crate) mod token; pub(crate) mod misc; pub(crate) mod wasm; + +#[cfg(test)] +pub(crate) mod test_support; diff --git a/crates/icp-cli/src/operations/settings.rs b/crates/icp-cli/src/operations/settings.rs index c8f1d0b8a..ff8339919 100644 --- a/crates/icp-cli/src/operations/settings.rs +++ b/crates/icp-cli/src/operations/settings.rs @@ -20,7 +20,7 @@ use num_traits::ToPrimitive; use snafu::{ResultExt, Snafu}; use tracing::{error, warn}; -use crate::progress::{ProgressManager, ProgressManagerSettings}; +use icp_events::{Reporter, TaskKind}; use super::proxy::UpdateOrProxyError; use super::proxy_management; @@ -226,23 +226,22 @@ pub(crate) async fn sync_settings_many( proxy: Option, target_canisters: Vec<(Principal, Canister)>, ids: IdMapping, - debug: bool, + reporter: &Reporter, ) -> Result<(), SyncSettingsManyError> { let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: debug }); let ids = Arc::new(ids); for (cid, info) in target_canisters { - let pb = progress_manager.create_progress_bar(&info.name); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let task = reporter.task(TaskKind::Spinner, info.name.as_str()); let canister_name = info.name.clone(); let ids = ids.clone(); let settings_fn = { let agent = agent.clone(); - let pb = pb.clone(); async move { - pb.set_message("Updating canister settings..."); let unresolved = sync_settings(&agent, proxy, &cid, &info, &ids).await?; for name in &unresolved { warn!( @@ -256,13 +255,15 @@ pub(crate) async fn sync_settings_many( }; futs.push_back(async move { - let result = ProgressManager::execute_with_progress( - &pb, - settings_fn, - || "Canister settings updated successfully".to_string(), - |err| format!("Failed to update canister settings: {err}"), - ) - .await; + task.message("Updating canister settings..."); + + let result = task + .run( + settings_fn, + || "Canister settings updated successfully".to_string(), + |err| format!("Failed to update canister settings: {err}"), + ) + .await; // Map error to include canister context for deferred printing result.map_err(|error| SettingsFailure { @@ -563,3 +564,98 @@ mod tests { assert!(environment_variables_eq(&vars1, &vars2)); } } + +#[cfg(test)] +mod reporting_tests { + use super::*; + use crate::operations::test_support::{ + bare_canister, outcome_of, recording_reporter, task_labels, unreachable_agent, + }; + use icp_events::{Event, Outcome, TaskId, TaskKind}; + + fn canister_id() -> Principal { + Principal::from_text("ryjl3-tyaaa-aaaaa-aaaba-cai").unwrap() + } + + /// The agent cannot be reached, so this pins the reporting shape — start, + /// message, failure verdict — rather than the wording of the transport error. + #[tokio::test] + async fn an_unreachable_canister_is_reported_as_a_failure() { + let (reporter, sink) = recording_reporter(); + + let result = sync_settings_many( + unreachable_agent(), + None, + vec![(canister_id(), bare_canister("backend"))], + IdMapping::new(), + &reporter, + ) + .await; + + assert!(result.is_err()); + + let events = sink.events(); + assert_eq!( + events[..2], + [ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskMessage { + id: TaskId(0), + message: "Updating canister settings...".into(), + }, + ] + ); + + let (outcome, message) = outcome_of(&events, TaskId(0)); + assert_eq!(outcome, Outcome::Failure); + assert!( + message + .as_deref() + .is_some_and(|m| m.starts_with("Failed to update canister settings: ")), + "unexpected message: {message:?}" + ); + } + + #[tokio::test] + async fn one_task_per_canister_in_the_given_order() { + let (reporter, sink) = recording_reporter(); + + let _ = sync_settings_many( + unreachable_agent(), + None, + vec![ + (canister_id(), bare_canister("frontend")), + (canister_id(), bare_canister("backend")), + ], + IdMapping::new(), + &reporter, + ) + .await; + + assert_eq!( + task_labels(&sink.events()), + vec![Some("frontend".to_string()), Some("backend".to_string())] + ); + } + + #[tokio::test] + async fn nothing_to_sync_reports_nothing() { + let (reporter, sink) = recording_reporter(); + + let result = sync_settings_many( + unreachable_agent(), + None, + Vec::new(), + IdMapping::new(), + &reporter, + ) + .await; + + assert!(result.is_ok()); + assert!(sink.events().is_empty()); + } +} diff --git a/crates/icp-cli/src/operations/test_support.rs b/crates/icp-cli/src/operations/test_support.rs new file mode 100644 index 000000000..9f31cba81 --- /dev/null +++ b/crates/icp-cli/src/operations/test_support.rs @@ -0,0 +1,98 @@ +//! Fixtures shared by the operation unit tests. +//! +//! Operations report through an [`icp_events::Reporter`], so a test can run one for +//! real and assert on the `Vec` it produced — no terminal, and no need to +//! inspect what a progress bar happened to draw. + +use std::collections::BTreeMap; +use std::sync::Arc; + +use async_trait::async_trait; +use ic_agent::Agent; +use icp::Canister; +use icp::canister::Settings; +use icp::manifest::{BuildSteps, SyncSteps}; +use icp::store_artifact::{Access, LookupArtifactError, SaveError}; +use icp_events::{Event, Outcome, RecordingSink, Reporter, TaskId}; + +/// A reporter that records everything instead of drawing it. +pub(crate) fn recording_reporter() -> (Reporter, Arc) { + let sink = Arc::new(RecordingSink::new()); + (Reporter::new(sink.clone()), sink) +} + +/// An artifact store that holds nothing, so every lookup misses. +/// +/// Lets the install path be exercised without a network: the missing artifact is +/// found before the agent is ever touched. +#[derive(Debug, Default)] +pub(crate) struct EmptyArtifacts; + +#[async_trait] +impl Access for EmptyArtifacts { + async fn save(&self, _name: &str, _wasm: &[u8]) -> Result<(), SaveError> { + Ok(()) + } + + async fn lookup(&self, name: &str) -> Result, LookupArtifactError> { + Err(LookupArtifactError::LookupArtifactNotFound { + name: name.to_owned(), + }) + } +} + +/// An agent aimed at a port nothing listens on, so every call fails locally. +pub(crate) fn unreachable_agent() -> Agent { + Agent::builder() + .with_url("http://127.0.0.1:1") + .build() + .expect("agent with a well-formed url should build") +} + +/// A minimal canister with no build or sync steps. +pub(crate) fn bare_canister(name: &str) -> Canister { + Canister { + name: name.to_string(), + settings: Settings::default(), + build: BuildSteps { steps: Vec::new() }, + sync: SyncSteps::default(), + init_args: None, + registry_recipe: None, + bindings: BTreeMap::new(), + friendly_names: vec![name.to_string()], + environment_variable_files: BTreeMap::new(), + } +} + +/// The `(outcome, message)` of the single `TaskFinished` event for `id`. +/// +/// Panics unless exactly one such event exists, which is itself the assertion that +/// every task is closed out once and only once. +pub(crate) fn outcome_of(events: &[Event], id: TaskId) -> (Outcome, Option) { + let mut finishes = events.iter().filter_map(|event| match event { + Event::TaskFinished { + id: finished, + outcome, + message, + } if *finished == id => Some((*outcome, message.clone())), + _ => None, + }); + + let finish = finishes.next().unwrap_or_else(|| { + panic!("no TaskFinished event for {id:?}"); + }); + assert!(finishes.next().is_none(), "{id:?} finished more than once"); + + finish +} + +/// The labels of every task, in the order the tasks were started. +pub(crate) fn task_labels(events: &[Event]) -> Vec> { + events + .iter() + .filter_map(|event| match event { + Event::TaskStarted { label, .. } => Some(label.clone()), + _ => None, + }) + .collect() +} diff --git a/crates/icp-cli/src/progress.rs b/crates/icp-cli/src/progress.rs index 0a0795991..0b3261c4f 100644 --- a/crates/icp-cli/src/progress.rs +++ b/crates/icp-cli/src/progress.rs @@ -22,6 +22,24 @@ const COLOR_REGULAR: &str = "blue"; const COLOR_SUCCESS: &str = "green"; const COLOR_FAILURE: &str = "red"; +/// The style a spinner carries while it is still running. +pub(crate) fn running_style() -> ProgressStyle { + make_style(TICK_EMPTY, COLOR_REGULAR) +} + +/// The style a spinner carries once it has succeeded. +pub(crate) fn success_style() -> ProgressStyle { + make_style(TICK_SUCCESS, COLOR_SUCCESS) +} + +/// The style a spinner carries once it has failed. +pub(crate) fn failure_style() -> ProgressStyle { + make_style(TICK_FAILURE, COLOR_FAILURE) +} + +/// How often a running spinner redraws itself. +pub(crate) const STEADY_TICK: Duration = Duration::from_millis(120); + // Creates a progress bar style with a spinner that transitions to a final tick symbol // - end_tick: the symbol to display when the progress completes (success, failure, etc.) // - color: the color theme for the spinner and text @@ -101,13 +119,10 @@ impl ProgressManager { pub(crate) fn create_independent_progress_bar(&self) -> SimpleProgressBar { let pb = self .multi_progress - .add(SimpleProgressBar::new_spinner().with_style(make_style( - TICK_EMPTY, // end_tick - COLOR_REGULAR, // color - ))); + .add(SimpleProgressBar::new_spinner().with_style(running_style())); // Auto-tick spinner - pb.enable_steady_tick(Duration::from_millis(120)); + pb.enable_steady_tick(STEADY_TICK); pb } @@ -166,11 +181,9 @@ impl ProgressManager { // Update the progress bar style and message based on result let (style, message) = match &result { - Ok(_) => (make_style(TICK_SUCCESS, COLOR_SUCCESS), success_message()), - Err(err) if is_success_error(err) => { - (make_style(TICK_SUCCESS, COLOR_SUCCESS), error_message(err)) - } - Err(err) => (make_style(TICK_FAILURE, COLOR_FAILURE), error_message(err)), + Ok(_) => (success_style(), success_message()), + Err(err) if is_success_error(err) => (success_style(), error_message(err)), + Err(err) => (failure_style(), error_message(err)), }; progress_bar.set_style(style); diff --git a/crates/icp-events/Cargo.toml b/crates/icp-events/Cargo.toml new file mode 100644 index 000000000..74614cedc --- /dev/null +++ b/crates/icp-events/Cargo.toml @@ -0,0 +1,23 @@ +# The event model is deliberately NOT semver-stable: it ships at 0.x and moves in +# lockstep with `icp-cli`. Nothing here is published. +[package] +name = "icp-events" +version = "0.1.0" +edition = { workspace = true } +license = { workspace = true } +repository = { workspace = true } +publish = false + +# Dependencies are intentionally limited to serde and futures. `icp-events` must stay +# free of `icp`, of any async runtime, and of anything terminal-shaped (indicatif, +# dialoguer, clap, console) so that operations can depend on it without depending on +# the CLI binary. +[dependencies] +futures = { workspace = true } +serde = { workspace = true } + +[dev-dependencies] +serde_json = { workspace = true } + +[lints] +workspace = true diff --git a/crates/icp-events/src/cancel.rs b/crates/icp-events/src/cancel.rs new file mode 100644 index 000000000..f12e31702 --- /dev/null +++ b/crates/icp-events/src/cancel.rs @@ -0,0 +1,173 @@ +use std::{ + future::Future, + pin::Pin, + sync::{ + Arc, Mutex, + atomic::{AtomicBool, Ordering}, + }, + task::{Context, Poll, Waker}, +}; + +use futures::future::{Either, select}; + +/// A cooperative cancellation signal shared by everything a [`Reporter`](crate::Reporter) +/// hands out. +/// +/// Deliberately runtime-agnostic: it is a flag plus a waker list, so operations can +/// wait on cancellation without pulling in an async runtime. +#[derive(Debug, Clone, Default)] +pub struct CancelToken { + inner: Arc, +} + +#[derive(Debug, Default)] +struct Inner { + cancelled: AtomicBool, + wakers: Mutex>, +} + +impl CancelToken { + /// A fresh, uncancelled token. + pub fn new() -> Self { + Self::default() + } + + /// Trip the token and wake everything waiting on it. Idempotent. + pub fn cancel(&self) { + if self.inner.cancelled.swap(true, Ordering::SeqCst) { + return; + } + + let wakers = std::mem::take(&mut *self.inner.wakers.lock().expect("cancel token poisoned")); + for waker in wakers { + waker.wake(); + } + } + + /// Whether [`cancel`](CancelToken::cancel) has been called. + pub fn is_cancelled(&self) -> bool { + self.inner.cancelled.load(Ordering::SeqCst) + } + + /// A future that resolves once the token is cancelled. + pub fn cancelled(&self) -> Cancelled { + Cancelled { + inner: self.inner.clone(), + registered: false, + } + } + + /// Run `future` unless cancellation wins the race. + /// + /// Returns `None` if the token tripped first, in which case `future` is dropped + /// at its next suspension point. + pub async fn run_until(&self, future: F) -> Option { + let cancelled = self.cancelled(); + futures::pin_mut!(cancelled); + futures::pin_mut!(future); + + match select(cancelled, future).await { + Either::Left(((), _)) => None, + Either::Right((output, _)) => Some(output), + } + } +} + +/// The future returned by [`CancelToken::cancelled`]. +#[derive(Debug)] +pub struct Cancelled { + inner: Arc, + registered: bool, +} + +impl Future for Cancelled { + type Output = (); + + fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<()> { + let this = self.get_mut(); + + if this.inner.cancelled.load(Ordering::SeqCst) { + return Poll::Ready(()); + } + + // Register once, then re-check: `cancel` may have run between the load above + // and taking the lock, in which case our waker would never be woken. + if !this.registered { + let mut wakers = this.inner.wakers.lock().expect("cancel token poisoned"); + if this.inner.cancelled.load(Ordering::SeqCst) { + return Poll::Ready(()); + } + wakers.push(cx.waker().clone()); + this.registered = true; + } + + Poll::Pending + } +} + +#[cfg(test)] +mod tests { + use super::*; + use futures::executor::block_on; + + #[test] + fn starts_uncancelled_and_trips_once() { + let token = CancelToken::new(); + assert!(!token.is_cancelled()); + + token.cancel(); + assert!(token.is_cancelled()); + + // Idempotent. + token.cancel(); + assert!(token.is_cancelled()); + } + + #[test] + fn clones_share_one_signal() { + let token = CancelToken::new(); + let clone = token.clone(); + + clone.cancel(); + assert!(token.is_cancelled()); + } + + #[test] + fn cancelled_resolves_when_already_cancelled() { + let token = CancelToken::new(); + token.cancel(); + + block_on(token.cancelled()); + } + + #[test] + fn cancelled_wakes_a_pending_waiter() { + let token = CancelToken::new(); + let waiter = token.cancelled(); + + let cancel_from_another_thread = { + let token = token.clone(); + std::thread::spawn(move || token.cancel()) + }; + + block_on(waiter); + cancel_from_another_thread.join().unwrap(); + } + + #[test] + fn run_until_returns_the_output_when_not_cancelled() { + let token = CancelToken::new(); + assert_eq!(block_on(token.run_until(async { 42 })), Some(42)); + } + + #[test] + fn run_until_returns_none_when_already_cancelled() { + let token = CancelToken::new(); + token.cancel(); + + assert_eq!( + block_on(token.run_until(futures::future::pending::())), + None + ); + } +} diff --git a/crates/icp-events/src/event.rs b/crates/icp-events/src/event.rs new file mode 100644 index 000000000..e2b0a7c4c --- /dev/null +++ b/crates/icp-events/src/event.rs @@ -0,0 +1,229 @@ +use serde::{Deserialize, Serialize}; + +/// Identifies a task within a single [`Reporter`](crate::Reporter)'s event stream. +/// +/// Ids are only unique per reporter; two reporters both start counting at zero. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] +#[serde(transparent)] +pub struct TaskId(pub u64); + +/// The shape of a task, which tells a sink how to render it. +/// +/// This is a closed enum on purpose: the event model is not semver-stable, so new +/// shapes are added here rather than smuggled through an open string. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[serde(tag = "kind", rename_all = "snake_case")] +#[non_exhaustive] +pub enum TaskKind { + /// An open-ended activity whose duration is unknown, carrying only a message. + Spinner, + + /// An activity made of discrete steps, each of which streams output lines. + /// + /// `output_label` names the kind of output the steps produce (for example + /// `"Build"` or `"Sync"`) so a sink can label a replay of it. + Steps { output_label: String }, + + /// An activity that advances through a known number of bytes. + Bytes { total: u64 }, +} + +/// How a task ended. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] +#[serde(rename_all = "snake_case")] +#[non_exhaustive] +pub enum Outcome { + /// The task did what it set out to do. + Success, + + /// The task failed. + Failure, + + /// The task ended without either succeeding or failing — it was skipped, + /// superseded, or simply dropped. + Neutral, +} + +/// The severity of a [`Event::Notice`]. +/// +/// These mirror the user-facing `tracing` levels the CLI prints as product output; +/// they are not a logging facility. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Serialize, Deserialize)] +#[serde(rename_all = "snake_case")] +#[non_exhaustive] +pub enum NoticeLevel { + /// Plain user-facing output. + Info, + + /// Something the user should be aware of but which does not stop the operation. + Warn, + + /// Something that went wrong. + Error, +} + +/// A single observation emitted by an operation. +/// +/// Events are the entire vocabulary an operation has for talking to the user. A +/// terminal renders them as progress bars, a test records them into a `Vec`. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[serde(tag = "event", rename_all = "snake_case")] +#[non_exhaustive] +pub enum Event { + /// A task came into existence. Always the first event for a given `id`. + TaskStarted { + id: TaskId, + kind: TaskKind, + /// A short name for whatever the task acts on, usually a canister name. + label: Option, + }, + + /// The task's one-line status text changed. + TaskMessage { id: TaskId, message: String }, + + /// A [`TaskKind::Bytes`] task advanced to an absolute byte offset. + TaskPosition { id: TaskId, position: u64 }, + + /// The task ended. Always the last event for a given `id`. + TaskFinished { + id: TaskId, + outcome: Outcome, + message: Option, + }, + + /// A step of a [`TaskKind::Steps`] task began. `index` is zero-based. + StepStarted { + id: TaskId, + index: usize, + title: String, + }, + + /// A line of output produced by the step currently in progress. + StepOutput { id: TaskId, line: String }, + + /// The step with this `index` finished. + StepFinished { id: TaskId, index: usize }, + + /// A user-facing message that does not belong to any task. + Notice { level: NoticeLevel, message: String }, +} + +impl Event { + /// The task this event belongs to, if any. [`Event::Notice`] belongs to none. + pub fn task_id(&self) -> Option { + match *self { + Event::TaskStarted { id, .. } + | Event::TaskMessage { id, .. } + | Event::TaskPosition { id, .. } + | Event::TaskFinished { id, .. } + | Event::StepStarted { id, .. } + | Event::StepOutput { id, .. } + | Event::StepFinished { id, .. } => Some(id), + Event::Notice { .. } => None, + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn task_id_is_transparent_over_the_wire() { + let json = serde_json::to_string(&TaskId(7)).unwrap(); + assert_eq!(json, "7"); + assert_eq!(serde_json::from_str::("7").unwrap(), TaskId(7)); + } + + #[test] + fn events_round_trip_through_serde() { + let events = vec![ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskMessage { + id: TaskId(0), + message: "Installing...".into(), + }, + Event::TaskPosition { + id: TaskId(0), + position: 4096, + }, + Event::StepStarted { + id: TaskId(0), + index: 0, + title: "Building: step 1 of 2".into(), + }, + Event::StepOutput { + id: TaskId(0), + line: "compiling".into(), + }, + Event::StepFinished { + id: TaskId(0), + index: 0, + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Installed successfully".into()), + }, + Event::Notice { + level: NoticeLevel::Warn, + message: "not created yet".into(), + }, + ]; + + for event in events { + let json = serde_json::to_string(&event).unwrap(); + assert_eq!(serde_json::from_str::(&json).unwrap(), event); + } + } + + #[test] + fn task_kind_carries_all_three_shapes_in_use_today() { + // A plain spinner, a multi-step progress bar, and byte-position progress. + assert_eq!( + serde_json::to_value(TaskKind::Spinner).unwrap(), + serde_json::json!({ "kind": "spinner" }) + ); + assert_eq!( + serde_json::to_value(TaskKind::Steps { + output_label: "Build".into() + }) + .unwrap(), + serde_json::json!({ "kind": "steps", "output_label": "Build" }) + ); + assert_eq!( + serde_json::to_value(TaskKind::Bytes { total: 10 }).unwrap(), + serde_json::json!({ "kind": "bytes", "total": 10 }) + ); + } + + #[test] + fn only_notices_have_no_task_id() { + assert_eq!( + Event::TaskMessage { + id: TaskId(3), + message: "hi".into() + } + .task_id(), + Some(TaskId(3)) + ); + assert_eq!( + Event::Notice { + level: NoticeLevel::Info, + message: "hi".into() + } + .task_id(), + None + ); + } + + #[test] + fn notice_levels_are_ordered_by_severity() { + assert!(NoticeLevel::Info < NoticeLevel::Warn); + assert!(NoticeLevel::Warn < NoticeLevel::Error); + } +} diff --git a/crates/icp-events/src/lib.rs b/crates/icp-events/src/lib.rs new file mode 100644 index 000000000..6e8f518fb --- /dev/null +++ b/crates/icp-events/src/lib.rs @@ -0,0 +1,57 @@ +//! Progress and user-facing notices, expressed as data. +//! +//! Operations in `icp-cli` used to talk to the terminal directly through +//! `indicatif`, which welded them to the binary. This crate inverts that: an +//! operation is handed a [`Reporter`], reports what it is doing as [`Event`]s, and +//! never learns whether anything is rendering them. The CLI attaches an +//! [`EventSink`] that draws progress bars; a test attaches a [`RecordingSink`] and +//! asserts on a `Vec`. +//! +//! The model carries the three progress shapes the CLI uses today — a plain +//! spinner, a multi-step bar that streams command output, and byte-position +//! progress — plus [`Event::Notice`], which represents the user-facing `info!` / +//! `warn!` / `error!` calls that this CLI prints as product output rather than as +//! logging. +//! +//! # Stability +//! +//! The event model is **not** semver-stable. It ships at `0.x`, moves in lockstep +//! with `icp-cli`, and is never published. Enums are `#[non_exhaustive]` so +//! variants can be added without ceremony; [`TaskKind`] in particular is a closed +//! enum, not an open string, because nothing outside this workspace consumes it. +//! +//! The event stream does not drive `--json`. `--json` means the command's final +//! result, and progress never appears in it. +//! +//! # Example +//! +//! ``` +//! use std::sync::Arc; +//! use icp_events::{Event, Outcome, RecordingSink, Reporter, TaskId, TaskKind}; +//! +//! let sink = Arc::new(RecordingSink::new()); +//! let reporter = Reporter::new(sink.clone()); +//! +//! let task = reporter.task(TaskKind::Spinner, "backend"); +//! task.message("Installing..."); +//! task.succeed("Installed successfully"); +//! +//! assert_eq!( +//! sink.events().last().unwrap(), +//! &Event::TaskFinished { +//! id: TaskId(0), +//! outcome: Outcome::Success, +//! message: Some("Installed successfully".into()), +//! }, +//! ); +//! ``` + +mod cancel; +mod event; +mod reporter; +mod sink; + +pub use cancel::{CancelToken, Cancelled}; +pub use event::{Event, NoticeLevel, Outcome, TaskId, TaskKind}; +pub use reporter::{Reporter, Task}; +pub use sink::{DiscardSink, EventSink, RecordingSink}; diff --git a/crates/icp-events/src/reporter.rs b/crates/icp-events/src/reporter.rs new file mode 100644 index 000000000..ec98ae264 --- /dev/null +++ b/crates/icp-events/src/reporter.rs @@ -0,0 +1,588 @@ +use std::{ + fmt, + future::Future, + sync::{ + Arc, + atomic::{AtomicU64, Ordering}, + }, +}; + +use crate::{ + cancel::CancelToken, + event::{Event, NoticeLevel, Outcome, TaskId, TaskKind}, + sink::{DiscardSink, EventSink}, +}; + +/// The handle an operation is given so it can report what it is doing. +/// +/// A `Reporter` owns nothing terminal-shaped; it forwards [`Event`]s to an +/// [`EventSink`]. Clones share the sink, the id counter, and the cancel token. +#[derive(Clone)] +pub struct Reporter { + sink: Arc, + next_id: Arc, + cancel: CancelToken, +} + +impl fmt::Debug for Reporter { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("Reporter") + .field("sink", &self.sink) + .field("next_id", &self.next_id.load(Ordering::SeqCst)) + .field("cancel", &self.cancel) + .finish() + } +} + +impl Reporter { + /// Report to `sink`, with a fresh cancel token. + pub fn new(sink: Arc) -> Self { + Self::with_cancel_token(sink, CancelToken::new()) + } + + /// Report to `sink`, sharing an existing cancel token. + pub fn with_cancel_token(sink: Arc, cancel: CancelToken) -> Self { + Self { + sink, + next_id: Arc::new(AtomicU64::new(0)), + cancel, + } + } + + /// A reporter that throws everything away. + pub fn discard() -> Self { + Self::new(Arc::new(DiscardSink)) + } + + /// The cancellation signal shared with everything this reporter hands out. + pub fn cancel_token(&self) -> &CancelToken { + &self.cancel + } + + /// Send one event straight through to the sink. + pub fn emit(&self, event: Event) { + self.sink.emit(event); + } + + /// Emit a user-facing message that does not belong to any task. + pub fn notice(&self, level: NoticeLevel, message: impl Into) { + self.emit(Event::Notice { + level, + message: message.into(), + }); + } + + /// Emit an [`NoticeLevel::Info`] notice. + pub fn info(&self, message: impl Into) { + self.notice(NoticeLevel::Info, message); + } + + /// Emit a [`NoticeLevel::Warn`] notice. + pub fn warn(&self, message: impl Into) { + self.notice(NoticeLevel::Warn, message); + } + + /// Emit a [`NoticeLevel::Error`] notice. + pub fn error(&self, message: impl Into) { + self.notice(NoticeLevel::Error, message); + } + + /// Start a task labelled with the thing it acts on, usually a canister name. + pub fn task(&self, kind: TaskKind, label: impl Into) -> Task { + self.start(kind, Some(label.into())) + } + + /// Start a task that is not about any one named thing. + pub fn unlabelled_task(&self, kind: TaskKind) -> Task { + self.start(kind, None) + } + + fn start(&self, kind: TaskKind, label: Option) -> Task { + let id = TaskId(self.next_id.fetch_add(1, Ordering::SeqCst)); + self.emit(Event::TaskStarted { id, kind, label }); + + Task { + id, + reporter: self.clone(), + next_step: 0, + open_step: None, + finished: false, + } + } +} + +/// One unit of reportable work. +/// +/// A task always ends: finish it explicitly with [`succeed`](Task::succeed), +/// [`fail`](Task::fail), or [`skip`](Task::skip), or let it drop and it reports +/// [`Outcome::Neutral`]. That guarantee is what lets a sink close out a live +/// progress bar even on an early return. +#[derive(Debug)] +pub struct Task { + id: TaskId, + reporter: Reporter, + next_step: usize, + open_step: Option, + finished: bool, +} + +impl Task { + /// This task's id, as it appears in the event stream. + pub fn id(&self) -> TaskId { + self.id + } + + /// The reporter this task belongs to. + pub fn reporter(&self) -> &Reporter { + &self.reporter + } + + /// Replace the task's one-line status text. + pub fn message(&self, message: impl Into) { + self.reporter.emit(Event::TaskMessage { + id: self.id, + message: message.into(), + }); + } + + /// Report an absolute byte offset for a [`TaskKind::Bytes`] task. + pub fn position(&self, position: u64) { + self.reporter.emit(Event::TaskPosition { + id: self.id, + position, + }); + } + + /// Begin a step of a [`TaskKind::Steps`] task. + /// + /// # Panics + /// + /// Panics if a step is already in progress. + pub fn begin_step(&mut self, title: impl Into) { + assert!(self.open_step.is_none(), "step already in progress"); + + let index = self.next_step; + self.next_step += 1; + self.open_step = Some(index); + + self.reporter.emit(Event::StepStarted { + id: self.id, + index, + title: title.into(), + }); + } + + /// Report a line of output from the step in progress. + pub fn step_output(&self, line: impl Into) { + self.reporter.emit(Event::StepOutput { + id: self.id, + line: line.into(), + }); + } + + /// End the step in progress. + /// + /// # Panics + /// + /// Panics if no step is in progress. + pub fn end_step(&mut self) { + let index = self.open_step.take().expect("no step in progress"); + self.reporter + .emit(Event::StepFinished { id: self.id, index }); + } + + /// Finish the task successfully. + pub fn succeed(mut self, message: impl Into) { + self.complete(Outcome::Success, Some(message.into())); + } + + /// Finish the task as failed. + pub fn fail(mut self, message: impl Into) { + self.complete(Outcome::Failure, Some(message.into())); + } + + /// Finish the task without a verdict — skipped, superseded, or not applicable. + pub fn skip(mut self, message: impl Into) { + self.complete(Outcome::Neutral, Some(message.into())); + } + + /// Await `future`, then finish the task from its result. + /// + /// This is the shape shared by every "do one thing per canister and report how + /// it went" operation. + pub async fn run( + self, + future: F, + success_message: impl FnOnce() -> String, + error_message: impl FnOnce(&E) -> String, + ) -> Result + where + F: Future>, + { + self.run_with(future, success_message, error_message, |_| false) + .await + } + + /// [`run`](Task::run), but errors matching `is_success_error` are reported as + /// successes while still being returned to the caller. + pub async fn run_with( + mut self, + future: F, + success_message: impl FnOnce() -> String, + error_message: impl FnOnce(&E) -> String, + is_success_error: impl FnOnce(&E) -> bool, + ) -> Result + where + F: Future>, + { + let result = future.await; + + let (outcome, message) = match &result { + Ok(_) => (Outcome::Success, success_message()), + Err(err) if is_success_error(err) => (Outcome::Success, error_message(err)), + Err(err) => (Outcome::Failure, error_message(err)), + }; + self.complete(outcome, Some(message)); + + result + } + + fn complete(&mut self, outcome: Outcome, message: Option) { + if self.finished { + return; + } + self.finished = true; + + if self.open_step.is_some() { + self.end_step(); + } + + self.reporter.emit(Event::TaskFinished { + id: self.id, + outcome, + message, + }); + } +} + +impl Drop for Task { + fn drop(&mut self) { + // A dropped task still has to close out, or a sink is left holding a bar that + // spins forever. + self.complete(Outcome::Neutral, None); + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::sink::RecordingSink; + use futures::executor::block_on; + + fn recorder() -> (Reporter, Arc) { + let sink = Arc::new(RecordingSink::new()); + (Reporter::new(sink.clone()), sink) + } + + #[test] + fn a_spinner_task_reports_start_message_and_outcome() { + let (reporter, sink) = recorder(); + + let task = reporter.task(TaskKind::Spinner, "backend"); + task.message("Installing..."); + task.succeed("Installed successfully"); + + assert_eq!( + sink.events(), + vec![ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }, + Event::TaskMessage { + id: TaskId(0), + message: "Installing...".into(), + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Installed successfully".into()), + }, + ] + ); + } + + #[test] + fn task_ids_are_handed_out_in_creation_order() { + let (reporter, sink) = recorder(); + + let _a = reporter.task(TaskKind::Spinner, "a"); + let _b = reporter.task(TaskKind::Spinner, "b"); + + let ids: Vec<_> = sink.events().iter().filter_map(Event::task_id).collect(); + assert_eq!(ids, vec![TaskId(0), TaskId(1)]); + } + + #[test] + fn dropping_a_task_finishes_it_neutrally() { + let (reporter, sink) = recorder(); + + drop(reporter.task(TaskKind::Spinner, "abandoned")); + + assert_eq!( + sink.events().last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Neutral, + message: None, + } + ); + } + + #[test] + fn a_task_finishes_exactly_once() { + let (reporter, sink) = recorder(); + + reporter.task(TaskKind::Spinner, "once").skip("Skipped"); + + let finishes = sink + .events() + .iter() + .filter(|e| matches!(e, Event::TaskFinished { .. })) + .count(); + assert_eq!(finishes, 1); + } + + #[test] + fn steps_are_numbered_and_carry_their_output() { + let (reporter, sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("Building: step 1 of 2 cargo build"); + task.step_output("compiling"); + task.end_step(); + task.begin_step("Building: step 2 of 2 wasm-opt"); + task.end_step(); + task.succeed("Built successfully"); + + assert_eq!( + sink.events()[1..], + [ + Event::StepStarted { + id: TaskId(0), + index: 0, + title: "Building: step 1 of 2 cargo build".into(), + }, + Event::StepOutput { + id: TaskId(0), + line: "compiling".into(), + }, + Event::StepFinished { + id: TaskId(0), + index: 0, + }, + Event::StepStarted { + id: TaskId(0), + index: 1, + title: "Building: step 2 of 2 wasm-opt".into(), + }, + Event::StepFinished { + id: TaskId(0), + index: 1, + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Built successfully".into()), + }, + ] + ); + } + + #[test] + fn finishing_closes_a_step_left_open() { + let (reporter, sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("Building: step 1 of 1"); + task.fail("Failed to build canister: boom"); + + assert_eq!( + sink.events()[2..], + [ + Event::StepFinished { + id: TaskId(0), + index: 0, + }, + Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Failure, + message: Some("Failed to build canister: boom".into()), + }, + ] + ); + } + + #[test] + #[should_panic(expected = "step already in progress")] + fn steps_may_not_overlap() { + let (reporter, _sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("one"); + task.begin_step("two"); + } + + #[test] + fn byte_tasks_report_absolute_positions() { + let (reporter, sink) = recorder(); + + let task = reporter.unlabelled_task(TaskKind::Bytes { total: 100 }); + task.position(0); + task.position(64); + drop(task); + + assert_eq!( + sink.events()[..3], + [ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Bytes { total: 100 }, + label: None, + }, + Event::TaskPosition { + id: TaskId(0), + position: 0, + }, + Event::TaskPosition { + id: TaskId(0), + position: 64, + }, + ] + ); + } + + #[test] + fn run_reports_success_and_returns_the_value() { + let (reporter, sink) = recorder(); + + let result: Result = block_on(reporter.task(TaskKind::Spinner, "ok").run( + async { Ok(7) }, + || "Compatible".to_string(), + |e: &String| format!("Incompatible: {e}"), + )); + + assert_eq!(result, Ok(7)); + assert_eq!( + sink.events().last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Compatible".into()), + } + ); + } + + #[test] + fn run_reports_failure_and_returns_the_error() { + let (reporter, sink) = recorder(); + + let result: Result = block_on(reporter.task(TaskKind::Spinner, "bad").run( + async { Err("boom".to_string()) }, + || "Compatible".to_string(), + |e: &String| format!("Incompatible: {e}"), + )); + + assert_eq!(result, Err("boom".to_string())); + assert_eq!( + sink.events().last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Failure, + message: Some("Incompatible: boom".into()), + } + ); + } + + #[test] + fn run_with_can_report_an_error_as_a_success() { + let (reporter, sink) = recorder(); + + let result: Result = + block_on(reporter.task(TaskKind::Spinner, "soft").run_with( + async { Err("already done".to_string()) }, + || "Done".to_string(), + |e: &String| format!("Nothing to do: {e}"), + |e: &String| e == "already done", + )); + + assert!(result.is_err()); + assert_eq!( + sink.events().last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Nothing to do: already done".into()), + } + ); + } + + #[test] + fn notices_carry_their_level_and_no_task() { + let (reporter, sink) = recorder(); + + reporter.info("Installing canisters:"); + reporter.warn("not created yet"); + reporter.error("it broke"); + + assert_eq!( + sink.events(), + vec![ + Event::Notice { + level: NoticeLevel::Info, + message: "Installing canisters:".into(), + }, + Event::Notice { + level: NoticeLevel::Warn, + message: "not created yet".into(), + }, + Event::Notice { + level: NoticeLevel::Error, + message: "it broke".into(), + }, + ] + ); + } + + #[test] + fn a_discarding_reporter_still_works() { + let reporter = Reporter::discard(); + reporter.task(TaskKind::Spinner, "quiet").succeed("done"); + reporter.info("also quiet"); + } + + #[test] + fn clones_share_the_cancel_token() { + let (reporter, _sink) = recorder(); + let clone = reporter.clone(); + + clone.cancel_token().cancel(); + assert!(reporter.cancel_token().is_cancelled()); + } +} diff --git a/crates/icp-events/src/sink.rs b/crates/icp-events/src/sink.rs new file mode 100644 index 000000000..aead89a46 --- /dev/null +++ b/crates/icp-events/src/sink.rs @@ -0,0 +1,134 @@ +use std::{ + fmt, + sync::{Arc, Mutex}, +}; + +use crate::event::Event; + +/// The destination for the events an operation emits. +/// +/// Implementations must be cheap and non-blocking: [`emit`](EventSink::emit) is +/// called from inside operations, often while other work is in flight. +pub trait EventSink: fmt::Debug + Send + Sync { + /// Record or render a single event. + fn emit(&self, event: Event); +} + +impl EventSink for Arc { + fn emit(&self, event: Event) { + (**self).emit(event); + } +} + +/// A sink that throws every event away. +/// +/// Useful for code paths that should stay silent, and as a default in tests that +/// do not care about output. +#[derive(Debug, Clone, Copy, Default)] +pub struct DiscardSink; + +impl EventSink for DiscardSink { + fn emit(&self, _event: Event) {} +} + +/// A sink that keeps every event it is given, in order. +/// +/// This is what makes operations unit-testable: run the operation against a +/// `RecordingSink` and assert on the resulting `Vec`. +#[derive(Debug, Default)] +pub struct RecordingSink { + events: Mutex>, +} + +impl RecordingSink { + /// Create an empty recorder. + pub fn new() -> Self { + Self::default() + } + + /// A snapshot of everything recorded so far, in emission order. + pub fn events(&self) -> Vec { + self.events.lock().expect("recording sink poisoned").clone() + } + + /// Drain everything recorded so far, leaving the recorder empty. + pub fn take(&self) -> Vec { + std::mem::take(&mut *self.events.lock().expect("recording sink poisoned")) + } +} + +impl EventSink for RecordingSink { + fn emit(&self, event: Event) { + self.events + .lock() + .expect("recording sink poisoned") + .push(event); + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::event::{NoticeLevel, TaskId}; + + fn notice(message: &str) -> Event { + Event::Notice { + level: NoticeLevel::Info, + message: message.into(), + } + } + + #[test] + fn recording_sink_preserves_order() { + let sink = RecordingSink::new(); + sink.emit(notice("one")); + sink.emit(notice("two")); + + assert_eq!(sink.events(), vec![notice("one"), notice("two")]); + } + + #[test] + fn take_drains_the_recorder() { + let sink = RecordingSink::new(); + sink.emit(notice("one")); + + assert_eq!(sink.take(), vec![notice("one")]); + assert!(sink.events().is_empty()); + } + + #[test] + fn discard_sink_keeps_nothing() { + // Nothing to assert beyond it not panicking; it exists so silent code paths + // do not need an `Option`. + DiscardSink.emit(notice("dropped")); + } + + #[test] + fn arc_forwards_to_the_inner_sink() { + let sink = Arc::new(RecordingSink::new()); + EventSink::emit(&sink, notice("through the arc")); + + assert_eq!(sink.events(), vec![notice("through the arc")]); + } + + #[test] + fn sinks_are_usable_from_several_threads() { + let sink = Arc::new(RecordingSink::new()); + let threads: Vec<_> = (0..4) + .map(|i| { + let sink = sink.clone(); + std::thread::spawn(move || { + sink.emit(Event::TaskMessage { + id: TaskId(i), + message: format!("from {i}"), + }) + }) + }) + .collect(); + for t in threads { + t.join().unwrap(); + } + + assert_eq!(sink.events().len(), 4); + } +} From 93a3017f404907d4475d8019316219c7b5aba7af Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Thu, 13 Aug 2026 09:16:44 +0000 Subject: [PATCH 02/14] no-mistakes(review): fix CancelToken waker lifecycle and neutral-finish test --- crates/icp-cli/src/events.rs | 28 +++-- crates/icp-events/src/cancel.rs | 185 +++++++++++++++++++++++++++++--- 2 files changed, 194 insertions(+), 19 deletions(-) diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 211df24fa..28408ba4b 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -251,7 +251,7 @@ mod rendering_equivalence { /// A terminal that remembers what was written to it. #[derive(Debug, Clone, Default)] - struct RecordingTerm { + pub(super) struct RecordingTerm { writes: Arc>>, } @@ -268,7 +268,7 @@ mod rendering_equivalence { /// dropped on the way: the blank line indicatif writes to pad out the rest of /// the terminal row, which is a function of the frame it follows, and the /// animation glyph, which advances on a timer and so differs run to run. - fn frames(&self) -> Vec { + pub(super) fn frames(&self) -> Vec { let mut frames: Vec = self .writes .lock() @@ -339,7 +339,7 @@ mod rendering_equivalence { } } - fn recording_target(term: &RecordingTerm) -> ProgressDrawTarget { + pub(super) fn recording_target(term: &RecordingTerm) -> ProgressDrawTarget { ProgressDrawTarget::term_like(Box::new(term.clone())) } @@ -470,7 +470,10 @@ mod rendering_equivalence { #[cfg(test)] mod tests { - use super::*; + use super::{ + rendering_equivalence::{RecordingTerm, recording_target}, + *, + }; /// Hidden bars still track state, so the sink can be exercised without a tty. fn sink() -> IndicatifSink { @@ -632,9 +635,13 @@ mod tests { assert_eq!(bars[&TaskId(0)].bar.message(), "second\n│ new\n└\n\n"); } + /// The bar is gone from the map by the time `finish` returns, so the message has + /// to be observed where it actually lands: on the terminal. #[test] - fn a_neutral_finish_keeps_its_message() { - let sink = sink(); + fn a_neutral_finish_draws_its_message_before_closing_the_bar_out() { + let term = RecordingTerm::default(); + let sink = IndicatifSink::with_draw_target(recording_target(&term)); + sink.emit(Event::TaskStarted { id: TaskId(0), kind: TaskKind::Spinner, @@ -647,6 +654,15 @@ mod tests { }); assert_eq!(live_bars(&sink), 0); + + let frames = term.frames(); + assert!( + frames + .iter() + .any(|frame| frame.contains("[backend]") + && frame.contains("Skipped (not an upgrade)")), + "frames: {frames:?}" + ); } #[test] diff --git a/crates/icp-events/src/cancel.rs b/crates/icp-events/src/cancel.rs index f12e31702..0b70ef169 100644 --- a/crates/icp-events/src/cancel.rs +++ b/crates/icp-events/src/cancel.rs @@ -1,4 +1,5 @@ use std::{ + collections::HashMap, future::Future, pin::Pin, sync::{ @@ -23,7 +24,19 @@ pub struct CancelToken { #[derive(Debug, Default)] struct Inner { cancelled: AtomicBool, - wakers: Mutex>, + waiters: Mutex, +} + +/// The waiters currently parked on a token. +/// +/// Keyed rather than a bare `Vec` so that a [`Cancelled`] which is dropped before the +/// token ever trips can take its own registration back out again; otherwise a token +/// shared across an operation would accumulate a waker per completed wait. +#[derive(Debug, Default)] +struct Waiters { + /// Never reused, so a stale id can never name someone else's slot. + next_id: u64, + wakers: HashMap, } impl CancelToken { @@ -38,8 +51,15 @@ impl CancelToken { return; } - let wakers = std::mem::take(&mut *self.inner.wakers.lock().expect("cancel token poisoned")); - for waker in wakers { + let waiters = std::mem::take( + &mut self + .inner + .waiters + .lock() + .expect("cancel token poisoned") + .wakers, + ); + for waker in waiters.into_values() { waker.wake(); } } @@ -53,10 +73,21 @@ impl CancelToken { pub fn cancelled(&self) -> Cancelled { Cancelled { inner: self.inner.clone(), - registered: false, + registration: None, } } + /// How many waiters are currently parked on this token. + #[cfg(test)] + fn parked_waiters(&self) -> usize { + self.inner + .waiters + .lock() + .expect("cancel token poisoned") + .wakers + .len() + } + /// Run `future` unless cancellation wins the race. /// /// Returns `None` if the token tripped first, in which case `future` is dropped @@ -77,7 +108,8 @@ impl CancelToken { #[derive(Debug)] pub struct Cancelled { inner: Arc, - registered: bool, + /// Which slot in [`Waiters`] holds this future's waker, once it has parked. + registration: Option, } impl Future for Cancelled { @@ -87,28 +119,91 @@ impl Future for Cancelled { let this = self.get_mut(); if this.inner.cancelled.load(Ordering::SeqCst) { + // `cancel` already drained every waker, so there is no slot left to free. + this.registration = None; + return Poll::Ready(()); + } + + let mut waiters = this.inner.waiters.lock().expect("cancel token poisoned"); + + // Re-check under the lock: `cancel` may have run between the load above and + // taking it, in which case the waker stored below would never be woken. + if this.inner.cancelled.load(Ordering::SeqCst) { + this.registration = None; return Poll::Ready(()); } - // Register once, then re-check: `cancel` may have run between the load above - // and taking the lock, in which case our waker would never be woken. - if !this.registered { - let mut wakers = this.inner.wakers.lock().expect("cancel token poisoned"); - if this.inner.cancelled.load(Ordering::SeqCst) { - return Poll::Ready(()); + // The `Future` contract requires the *latest* waker to be the registered one: + // a re-poll can arrive from a different task than the last one. + match this.registration.and_then(|id| waiters.wakers.get_mut(&id)) { + Some(stored) => { + if !stored.will_wake(cx.waker()) { + *stored = cx.waker().clone(); + } + } + None => { + let id = waiters.next_id; + waiters.next_id += 1; + waiters.wakers.insert(id, cx.waker().clone()); + this.registration = Some(id); } - wakers.push(cx.waker().clone()); - this.registered = true; } Poll::Pending } } +impl Drop for Cancelled { + /// Give the slot back, so a token that outlives many waits does not accumulate + /// wakers for futures that finished without it ever tripping. + fn drop(&mut self) { + let Some(id) = self.registration.take() else { + return; + }; + + if let Ok(mut waiters) = self.inner.waiters.lock() { + waiters.wakers.remove(&id); + } + } +} + #[cfg(test)] mod tests { use super::*; use futures::executor::block_on; + use std::{ + sync::atomic::AtomicUsize, + task::{Wake, Waker}, + }; + + /// A waker that only records whether it was woken. + #[derive(Debug, Default)] + struct CountingWaker(AtomicUsize); + + impl CountingWaker { + fn wakes(&self) -> usize { + self.0.load(Ordering::SeqCst) + } + } + + impl Wake for CountingWaker { + fn wake(self: Arc) { + self.wake_by_ref(); + } + + fn wake_by_ref(self: &Arc) { + self.0.fetch_add(1, Ordering::SeqCst); + } + } + + /// Poll `waiter` once with `waker`, asserting it parks. + fn poll_pending(waiter: &mut Cancelled, waker: &Waker) { + assert!( + Pin::new(waiter) + .poll(&mut Context::from_waker(waker)) + .is_pending() + ); + } #[test] fn starts_uncancelled_and_trips_once() { @@ -170,4 +265,68 @@ mod tests { None ); } + + /// A re-poll can come from a different task than the one that parked, so the + /// waker registered last is the only one guaranteed to still be live. + #[test] + fn a_repoll_moves_the_wakeup_to_the_newest_waker() { + let token = CancelToken::new(); + let mut waiter = token.cancelled(); + + let stale = Arc::new(CountingWaker::default()); + let fresh = Arc::new(CountingWaker::default()); + + poll_pending(&mut waiter, &Waker::from(stale.clone())); + poll_pending(&mut waiter, &Waker::from(fresh.clone())); + + token.cancel(); + + assert_eq!(stale.wakes(), 0, "the waker replaced on re-poll was woken"); + assert_eq!(fresh.wakes(), 1); + assert!( + Pin::new(&mut waiter) + .poll(&mut Context::from_waker(&Waker::from(fresh))) + .is_ready() + ); + } + + #[test] + fn repolling_with_the_same_waker_parks_only_once() { + let token = CancelToken::new(); + let mut waiter = token.cancelled(); + let waker = Waker::from(Arc::new(CountingWaker::default())); + + poll_pending(&mut waiter, &waker); + poll_pending(&mut waiter, &waker); + poll_pending(&mut waiter, &waker); + + assert_eq!(token.parked_waiters(), 1); + } + + #[test] + fn a_dropped_waiter_takes_its_registration_with_it() { + let token = CancelToken::new(); + let waker = Waker::from(Arc::new(CountingWaker::default())); + + for _ in 0..100 { + let mut waiter = token.cancelled(); + poll_pending(&mut waiter, &waker); + assert_eq!(token.parked_waiters(), 1); + } + + assert_eq!(token.parked_waiters(), 0); + } + + /// The same token is handed to every operation, so waits that end without + /// cancellation must not leave anything behind. + #[test] + fn run_until_leaves_nothing_parked_when_the_future_wins() { + let token = CancelToken::new(); + + for _ in 0..100 { + assert_eq!(block_on(token.run_until(async { 42 })), Some(42)); + } + + assert_eq!(token.parked_waiters(), 0); + } } From c4c4189070c8a14682d444e20e781fc79facecb6 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Thu, 13 Aug 2026 09:39:13 +0000 Subject: [PATCH 03/14] no-mistakes(review): share byte bar style and correct progress docs --- .claude/architecture.md | 10 +- crates/icp-cli/src/events.rs | 118 ++++++++++++++++-- .../src/operations/snapshot_transfer.rs | 10 +- crates/icp-cli/src/progress.rs | 8 ++ 4 files changed, 126 insertions(+), 20 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index 9096a33a8..61ba49e42 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -88,8 +88,14 @@ async runtime, or anything terminal-shaped. `crates/icp-cli/src/events.rs` holds - New or converted operations take a `&Reporter`, never a `debug: bool` and never `crate::progress` directly. Callers build one per operation with `events::indicatif_reporter(ctx.debug)`. -- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer, kept only while - `build.rs`, `sync.rs`, and `snapshot_transfer.rs` still use it. Do not add users. +- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer. Do not add users; it is + removable only once nothing imports it, which today includes commands as well as + operations — check with `rg 'crate::progress' crates/icp-cli/src` before assuming the + remaining users are only the unconverted operations. A few call sites (notably + `operations/snapshot_transfer.rs`) drive `indicatif` directly without going through + `progress.rs` at all, so `rg 'indicatif' crates/icp-cli/src` is the second half of that + inventory. Style definitions shared by both renderers (spinner styles, `STEADY_TICK`, + `byte_style`) live in `progress.rs` so the two cannot drift while both exist. - The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums `#[non_exhaustive]`, `TaskKind` closed. - Events do not drive `--json`. `--json` means the command's final result; progress never diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 28408ba4b..5a27def96 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -11,11 +11,13 @@ use std::{ }; use icp_events::{Event, EventSink, Outcome, Reporter, TaskId, TaskKind}; -use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget, ProgressStyle}; +use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget}; use itertools::Itertools; use tracing::debug; -use crate::progress::{RollingLines, STEADY_TICK, failure_style, running_style, success_style}; +use crate::progress::{ + RollingLines, STEADY_TICK, byte_style, failure_style, running_style, success_style, +}; /// How many lines of a step's output stay on screen while it runs. const VISIBLE_STEP_LINES: usize = 4; @@ -227,14 +229,6 @@ impl EventSink for IndicatifSink { } } -/// The template byte-transfer bars use. -fn byte_style() -> ProgressStyle { - ProgressStyle::default_bar() - .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") - .expect("invalid progress bar template") - .progress_chars("#>-") -} - /// Proof that the events path draws what `ProgressManager` drew. /// /// Both renderers are pointed at the same recording terminal and driven through the @@ -244,7 +238,10 @@ fn byte_style() -> ProgressStyle { #[cfg(test)] mod rendering_equivalence { use super::*; - use crate::progress::{ProgressManager, ProgressManagerSettings}; + use crate::{ + operations::snapshot_transfer::create_transfer_progress_bar, + progress::{ProgressManager, ProgressManagerSettings}, + }; use futures::executor::block_on; use indicatif::TermLike; use std::io; @@ -443,6 +440,105 @@ mod rendering_equivalence { assert_eq!(old, new); } + /// Every frame `create_transfer_progress_bar` — the pre-inversion byte bar, still used + /// by `canister snapshot download`/`upload` — draws at `position`. + fn old_byte_frames(position: u64) -> Vec { + let term = RecordingTerm::default(); + let bar = create_transfer_progress_bar(100, "WASM module"); + bar.set_draw_target(recording_target(&term)); + bar.set_position(position); + bar.tick(); + + term.frames() + } + + /// Every frame a `TaskKind::Bytes` task draws at the same position. + fn new_byte_frames(position: u64) -> Vec { + let term = RecordingTerm::default(); + let reporter = new_reporter(&term); + + let task = reporter.task(TaskKind::Bytes { total: 100 }, "WASM module"); + task.position(position); + + term.frames() + } + + /// The byte shape is still drawn the pre-inversion way by + /// `snapshot_transfer::create_transfer_progress_bar`. Both sides take their template + /// from `progress::byte_style`, and this pins that they stay interchangeable. + /// + /// Compared at rest, where the rate reads `0 B/s` on both sides: `{wide_bar}` is given + /// whatever width the rest of the line leaves over, so once a transfer is under way the + /// bar's own width is a function of how long the rate string happens to be. + #[test] + fn a_byte_task_draws_the_same_line_as_the_transfer_bar() { + let old = old_byte_frames(0); + let new = new_byte_frames(0); + + assert!( + old.last() + .is_some_and(|frame| frame.contains("WASM module") && frame.contains("0 B/100 B")), + "old frames: {old:?}" + ); + assert_eq!( + old.last().map(|frame| mask_timings(frame)), + new.last().map(|frame| mask_timings(frame)), + "old: {old:?}\nnew: {new:?}" + ); + } + + /// `progress_chars` is the part of the byte template the at-rest comparison above + /// cannot see, since nothing is filled in yet. + #[test] + fn both_byte_bars_fill_with_the_same_glyphs() { + for frames in [old_byte_frames(64), new_byte_frames(64)] { + let drawn = frames.last().expect("nothing was drawn"); + + assert!( + drawn.contains('#') && drawn.contains('>') && drawn.contains('-'), + "{drawn:?}" + ); + } + } + + /// Blank out the parts of a byte bar that are derived from wall-clock time: the + /// `[HH:MM:SS]` elapsed counter and the trailing `(rate, eta)`. + fn mask_timings(frame: &str) -> String { + let mut out = String::with_capacity(frame.len()); + let mut rest = frame; + + while let Some(open) = rest.find('[') { + out.push_str(&rest[..open]); + rest = &rest[open..]; + + if is_clock(&rest[1..]) { + out.push_str("[??:??:??]"); + rest = &rest[10..]; + } else { + out.push('['); + rest = &rest[1..]; + } + } + out.push_str(rest); + + if let Some(at) = out.rfind('(') { + out.truncate(at); + } + out + } + + /// Whether `s` opens with `HH:MM:SS]`. + fn is_clock(s: &str) -> bool { + let b = s.as_bytes(); + + b.len() >= 9 + && b[8] == b']' + && b[..8].iter().enumerate().all(|(i, c)| match i { + 2 | 5 => *c == b':', + _ => c.is_ascii_digit(), + }) + } + /// Several canisters share one `MultiProgress`, so their bars have to be added in /// the same order to land on the same lines. #[test] diff --git a/crates/icp-cli/src/operations/snapshot_transfer.rs b/crates/icp-cli/src/operations/snapshot_transfer.rs index 24a6388de..6f7f31ad5 100644 --- a/crates/icp-cli/src/operations/snapshot_transfer.rs +++ b/crates/icp-cli/src/operations/snapshot_transfer.rs @@ -15,11 +15,12 @@ use ic_management_canister_types::{ use super::proxy::UpdateOrProxyError; use super::proxy_management; +use crate::progress::byte_style; use icp::{ fs::lock::{DirectoryStructureLock, LWrite, LockError, PathsAccess}, prelude::*, }; -use indicatif::{ProgressBar, ProgressStyle}; +use indicatif::ProgressBar; use serde::{Deserialize, Serialize}; use snafu::{ResultExt, Snafu}; use tokio::{ @@ -427,12 +428,7 @@ where /// Create a progress bar for byte transfers. pub fn create_transfer_progress_bar(total_bytes: u64, label: &str) -> ProgressBar { let pb = ProgressBar::new(total_bytes); - pb.set_style( - ProgressStyle::default_bar() - .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") - .expect("invalid progress bar template") - .progress_chars("#>-"), - ); + pb.set_style(byte_style()); pb.set_prefix(label.to_string()); pb } diff --git a/crates/icp-cli/src/progress.rs b/crates/icp-cli/src/progress.rs index 0b3261c4f..c94404116 100644 --- a/crates/icp-cli/src/progress.rs +++ b/crates/icp-cli/src/progress.rs @@ -40,6 +40,14 @@ pub(crate) fn failure_style() -> ProgressStyle { /// How often a running spinner redraws itself. pub(crate) const STEADY_TICK: Duration = Duration::from_millis(120); +/// The style a byte-transfer bar carries. +pub(crate) fn byte_style() -> ProgressStyle { + ProgressStyle::default_bar() + .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") + .expect("invalid progress bar template") + .progress_chars("#>-") +} + // Creates a progress bar style with a spinner that transitions to a final tick symbol // - end_tick: the symbol to display when the progress completes (success, failure, etc.) // - color: the color theme for the spinner and text From 48fb0ad8d7308d5de3df65ca3a095ed0154f2e1d Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Thu, 13 Aug 2026 09:48:57 +0000 Subject: [PATCH 04/14] no-mistakes(review): document compiler as gate for progress.rs removal --- .claude/architecture.md | 24 ++++++++++++++++-------- 1 file changed, 16 insertions(+), 8 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index 61ba49e42..52a45d6cb 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -88,14 +88,22 @@ async runtime, or anything terminal-shaped. `crates/icp-cli/src/events.rs` holds - New or converted operations take a `&Reporter`, never a `debug: bool` and never `crate::progress` directly. Callers build one per operation with `events::indicatif_reporter(ctx.debug)`. -- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer. Do not add users; it is - removable only once nothing imports it, which today includes commands as well as - operations — check with `rg 'crate::progress' crates/icp-cli/src` before assuming the - remaining users are only the unconverted operations. A few call sites (notably - `operations/snapshot_transfer.rs`) drive `indicatif` directly without going through - `progress.rs` at all, so `rg 'indicatif' crates/icp-cli/src` is the second half of that - inventory. Style definitions shared by both renderers (spinner styles, `STEADY_TICK`, - `byte_style`) live in `progress.rs` so the two cannot drift while both exist. +- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer. Do not add users. Whether + it is removable is a question for the compiler — delete it and run + `cargo check -p icp-cli --all-targets`; no grep is the gate. To survey the call sites, + search for the symbols, not the module path, because a nested `use crate::{ …, + progress::{…} }` never spells `crate::progress` (which is exactly how `commands/deploy.rs` + hides from that search): + + ```bash + grep -rlE 'ProgressManager|MultiStepProgressBar|RollingLines|_style\(|indicatif' crates/icp-cli/src + ``` + + That covers commands as well as operations, and both kinds of user: those going through + `progress.rs` and those driving `indicatif` themselves. Styles shared by the two renderers + (spinner styles, `STEADY_TICK`, `byte_style`) live in `progress.rs` so they cannot drift + while both exist — `operations/snapshot_transfer.rs`, for one, takes `byte_style` from + there but still builds the bar with `indicatif` directly. - The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums `#[non_exhaustive]`, `TaskKind` closed. - Events do not drive `--json`. `--json` means the command's final result; progress never From 2cf993daa12de6ca6ee7c1863ab342ec4769ab96 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Thu, 13 Aug 2026 10:50:15 +0000 Subject: [PATCH 05/14] no-mistakes(document): clarify partial progress inversion in architecture doc --- .claude/architecture.md | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index 52a45d6cb..7d9a4ca26 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -80,10 +80,12 @@ Store management is in `crates/icp/src/store_id.rs`. ## Progress & User-Facing Output Operations in `crates/icp-cli/src/operations/` report progress as data, not as terminal -calls. `crates/icp-events` defines the vocabulary (`Event`, `Reporter`, `Task`, -`EventSink`, `CancelToken`) and depends only on serde and futures — never on `icp`, an -async runtime, or anything terminal-shaped. `crates/icp-cli/src/events.rs` holds -`IndicatifSink`, the only place that maps events onto `indicatif` bars. +calls — an inversion that is partway done, so `build.rs`, `sync.rs` and +`snapshot_transfer.rs` still render directly. `crates/icp-events` defines the vocabulary +(`Event`, `Reporter`, `Task`, `EventSink`, `CancelToken`) and depends only on serde and +futures — never on `icp`, an async runtime, or anything terminal-shaped. +`crates/icp-cli/src/events.rs` holds `IndicatifSink`, the only place that maps events onto +`indicatif` bars. - New or converted operations take a `&Reporter`, never a `debug: bool` and never `crate::progress` directly. Callers build one per operation with From 22e6581275c170416b098790daf06f8d73f03389 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Mon, 17 Aug 2026 19:50:04 +0000 Subject: [PATCH 06/14] fix(events): label a spinner before its ticker can draw `ProgressBar::enable_steady_tick` spawns a thread that draws a frame immediately, so a prefix set after that call races the first tick. On a machine slow enough to lose that race the bar drew a bare spinner before its label appeared, which made the rendering-equivalence tests fail on macOS while passing on Linux and Windows. Both renderers had the same ordering, so both could produce the stray frame; build each bar fully styled and labelled before it is shown and, for spinners, before the ticker starts. --- crates/icp-cli/src/events.rs | 56 ++++++++++++++++++++++++++-------- crates/icp-cli/src/progress.rs | 21 +++++++++---- 2 files changed, 59 insertions(+), 18 deletions(-) diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 5a27def96..dac83d53f 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -87,18 +87,24 @@ impl IndicatifSink { } fn start(&self, id: TaskId, kind: TaskKind, label: Option) { + // Every bar is fully styled and labelled *before* it can draw anything: only + // then is it added to the `MultiProgress` and, for spinners, given a ticker. + // `Ticker::new` ticks immediately on the thread it spawns, so a prefix set + // after `enable_steady_tick` races that first tick and can lose — which is + // what drew a stray unprefixed spinner frame. See + // `tests::a_spinner_is_labelled_before_its_first_tick`. let state = match kind { TaskKind::Bytes { total } => { - let bar = self.multi.add(ProgressBar::new(total)); - bar.set_style(byte_style()); // Byte bars label themselves undecorated; spinners wrap the name in // brackets. Both match what the code being replaced did. - if let Some(label) = label { - bar.set_prefix(label); - } + let bar = ProgressBar::new(total).with_style(byte_style()); + let bar = match label { + Some(label) => bar.with_prefix(label), + None => bar, + }; BarState { - bar, + bar: self.multi.add(bar), styled_spinner: false, step_title: None, visible: RollingLines::new(VISIBLE_STEP_LINES), @@ -107,13 +113,14 @@ impl IndicatifSink { // Spinners and multi-step bars are the same bar; only the message // differs, and steps build a richer one. _ => { - let bar = self - .multi - .add(ProgressBar::new_spinner().with_style(running_style())); + let bar = ProgressBar::new_spinner().with_style(running_style()); + let bar = match label { + Some(label) => bar.with_prefix(format!("[{label}]")), + None => bar, + }; + + let bar = self.multi.add(bar); bar.enable_steady_tick(STEADY_TICK); - if let Some(label) = label { - bar.set_prefix(format!("[{label}]")); - } BarState { bar, @@ -761,6 +768,31 @@ mod tests { ); } + /// `enable_steady_tick` spawns a thread that draws a frame straight away, so a + /// bar labelled after that call races its own first tick — and a slow enough + /// machine loses, drawing a bare spinner before the label appears. Waiting out + /// several tick intervals here means the ticker has certainly drawn: every frame + /// it produced has to carry the prefix. + #[test] + fn a_spinner_is_labelled_before_its_first_tick() { + let term = RecordingTerm::default(); + let sink = IndicatifSink::with_draw_target(recording_target(&term)); + + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Spinner, + label: Some("backend".into()), + }); + std::thread::sleep(STEADY_TICK * 3); + + let frames = term.frames(); + assert!(!frames.is_empty(), "the ticker never drew anything"); + assert!( + frames.iter().all(|frame| frame.contains("[backend]")), + "frames: {frames:?}" + ); + } + #[test] fn events_for_an_unknown_task_are_ignored() { let sink = sink(); diff --git a/crates/icp-cli/src/progress.rs b/crates/icp-cli/src/progress.rs index c94404116..befdb894b 100644 --- a/crates/icp-cli/src/progress.rs +++ b/crates/icp-cli/src/progress.rs @@ -119,15 +119,24 @@ impl ProgressManager { /// Create a new progress bar with standard configuration pub(crate) fn create_progress_bar(&self, canister_name: &str) -> SimpleProgressBar { - let pb = self.create_independent_progress_bar(); - pb.set_prefix(format!("[{canister_name}]")); - pb + self.start_spinner( + SimpleProgressBar::new_spinner() + .with_style(running_style()) + .with_prefix(format!("[{canister_name}]")), + ) } pub(crate) fn create_independent_progress_bar(&self) -> SimpleProgressBar { - let pb = self - .multi_progress - .add(SimpleProgressBar::new_spinner().with_style(running_style())); + self.start_spinner(SimpleProgressBar::new_spinner().with_style(running_style())) + } + + /// Show `pb` and start animating it. + /// + /// The bar must arrive fully configured: the ticker thread `enable_steady_tick` + /// spawns draws a frame immediately, so a prefix set afterwards races that first + /// tick and can lose, leaving a stray unprefixed frame on screen. + fn start_spinner(&self, pb: SimpleProgressBar) -> SimpleProgressBar { + let pb = self.multi_progress.add(pb); // Auto-tick spinner pb.enable_steady_tick(STEADY_TICK); From 5f810b57d0878e203ac2b2e6676507cf3c27432c Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Mon, 17 Aug 2026 20:16:27 +0000 Subject: [PATCH 07/14] refactor: report build, sync and transfer progress through icp-events MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Finishes the progress inversion. The three operations left on the old renderer now report through `icp-events`, both `crates/icp` ports stop taking a terminal-shaped channel, and `progress.rs` is gone. - `icp-events` gains `OutputWriter`: a cheap, cloneable handle for the lines a running step produces. It reports each line as a `StepOutput` event and keeps it in the task's step log, so an operation can replay the failing step once the bars are down. That replaces the tokio channel plus the background drain task that `MultiStepProgressBar` needed, and with it the `end_step().await` that only existed to wait for that drain. - `Build::build` and `Synchronize::sync` — and the script, prebuilt, wasm-resolve, plugin and script-runner paths under them — take `Option` instead of `Option>`. The sync plugin runtime reports lines directly rather than `try_send`-ing them at a bounded channel, so a noisy plugin no longer silently drops output. - `snapshot_transfer` reports byte positions as `TaskKind::Bytes` progress, resume offsets included, and no longer builds its own bar. - `build_many`, `sync_many` and `create_bundle` take a `Reporter`; their `debug: bool` becomes `all_step_output`, which is the only thing that flag still decided once hiding moved to the reporter. `indicatif` is now confined to `events.rs`, which is also where the styles live. The two bespoke spinners in `canister migrate-id` and `identity link web` still build their own bars; they never used `progress.rs` and their look does not fit the shared model. The old renderers are gone, so the rendering tests pin the frames they drew as literals, captured from them before they were deleted. --- Cargo.lock | 2 + crates/icp-cli/src/commands/build.rs | 6 +- .../commands/canister/snapshot/download.rs | 47 ++- .../src/commands/canister/snapshot/upload.rs | 47 ++- crates/icp-cli/src/commands/deploy.rs | 18 +- crates/icp-cli/src/commands/network/start.rs | 17 +- crates/icp-cli/src/commands/network/update.rs | 12 +- crates/icp-cli/src/commands/project/bundle.rs | 3 +- crates/icp-cli/src/commands/sync.rs | 2 + crates/icp-cli/src/events.rs | 383 +++++++++++------- crates/icp-cli/src/main.rs | 1 - crates/icp-cli/src/operations/build.rs | 237 ++++++++++- crates/icp-cli/src/operations/bundle.rs | 12 +- crates/icp-cli/src/operations/mod.rs | 1 + .../src/operations/snapshot_transfer.rs | 28 +- crates/icp-cli/src/operations/step_replay.rs | 133 ++++++ crates/icp-cli/src/operations/sync.rs | 268 ++++++++++-- crates/icp-cli/src/progress.rs | 364 ----------------- crates/icp-events/src/lib.rs | 2 + crates/icp-events/src/output.rs | 178 ++++++++ crates/icp-events/src/reporter.rs | 119 +++++- crates/icp-sync-plugin/Cargo.toml | 1 + crates/icp-sync-plugin/src/runtime.rs | 67 ++- crates/icp/Cargo.toml | 1 + crates/icp/src/canister/build/mod.rs | 8 +- crates/icp/src/canister/build/prebuilt.rs | 10 +- crates/icp/src/canister/build/script.rs | 55 ++- crates/icp/src/canister/script.rs | 14 +- crates/icp/src/canister/sync/mod.rs | 10 +- crates/icp/src/canister/sync/plugin.rs | 4 +- crates/icp/src/canister/sync/script.rs | 6 +- crates/icp/src/canister/wasm.rs | 24 +- crates/icp/src/manifest/mod.rs | 1 + 33 files changed, 1381 insertions(+), 700 deletions(-) create mode 100644 crates/icp-cli/src/operations/step_replay.rs delete mode 100644 crates/icp-cli/src/progress.rs create mode 100644 crates/icp-events/src/output.rs diff --git a/Cargo.lock b/Cargo.lock index 8b8e22736..bad15fc21 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3636,6 +3636,7 @@ dependencies = [ "ic-management-canister-types 0.8.0", "ic-utils", "icp-canister-interfaces", + "icp-events", "icp-sync-plugin", "icrc-ledger-types", "indexmap", @@ -3792,6 +3793,7 @@ dependencies = [ "hex", "ic-agent", "icp-canister-interfaces", + "icp-events", "snafu", "tokio", "wasmtime", diff --git a/crates/icp-cli/src/commands/build.rs b/crates/icp-cli/src/commands/build.rs index d462f75f2..5929fc56b 100644 --- a/crates/icp-cli/src/commands/build.rs +++ b/crates/icp-cli/src/commands/build.rs @@ -6,7 +6,8 @@ use icp::context::{Context, EnvironmentSelection}; use tracing::info; use crate::{ - operations::build::build_many_with_progress_bar, + events::indicatif_reporter, + operations::build::build_many, options::{EnvironmentOpt, arg_struct_change_help}, }; @@ -57,12 +58,13 @@ pub(crate) async fn exec(ctx: &Context, args: &BuildArgs) -> Result<(), anyhow:: // Build the selected canisters info!("Building canisters:"); - build_many_with_progress_bar( + build_many( canisters_to_build, environment_selection.name(), ctx.builder.clone(), ctx.artifacts.clone(), &ctx.dirs.package_cache()?, + &indicatif_reporter(ctx.debug), ctx.debug, ) .await?; diff --git a/crates/icp-cli/src/commands/canister/snapshot/download.rs b/crates/icp-cli/src/commands/canister/snapshot/download.rs index d8b3aa661..d58639008 100644 --- a/crates/icp-cli/src/commands/canister/snapshot/download.rs +++ b/crates/icp-cli/src/commands/canister/snapshot/download.rs @@ -3,15 +3,17 @@ use candid::Principal; use clap::{Args, ValueHint}; use icp::context::Context; use icp::prelude::*; +use icp_events::TaskKind; use tracing::info; use super::SnapshotId; use crate::commands::args; +use crate::events::indicatif_reporter; use crate::operations::misc::format_timestamp; use crate::operations::snapshot_transfer::{ - BlobType, SnapshotPaths, SnapshotTransferError, create_transfer_progress_bar, - delete_download_progress, download_blob_to_file, download_wasm_chunk, load_download_progress, - load_metadata, read_snapshot_metadata, save_metadata, + BlobType, SnapshotPaths, SnapshotTransferError, delete_download_progress, + download_blob_to_file, download_wasm_chunk, load_download_progress, load_metadata, + read_snapshot_metadata, save_metadata, }; /// Download a snapshot to local disk @@ -57,6 +59,11 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho let name = &args.cmd_args.canister; let snapshot_id = &args.snapshot_id.0; + // Transfer bars are drawn even under `--debug`, which is how they have always + // behaved: unlike the spinners, they carry the only indication that a long + // transfer is moving. + let transfers = indicatif_reporter(false); + // Open or create the snapshot directory with a lock let snapshot_dir = SnapshotPaths::new(args.output.clone())?; @@ -121,7 +128,12 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho // Download WASM module if metadata.wasm_module_size > 0 { if !progress.wasm_module.is_complete(metadata.wasm_module_size) { - let pb = create_transfer_progress_bar(metadata.wasm_module_size, "WASM module"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.wasm_module_size, + }, + "WASM module", + ); download_blob_to_file( &agent, args.proxy, @@ -131,10 +143,10 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho metadata.wasm_module_size, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("WASM module: already complete"); } @@ -143,7 +155,12 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho // Download WASM memory if metadata.wasm_memory_size > 0 { if !progress.wasm_memory.is_complete(metadata.wasm_memory_size) { - let pb = create_transfer_progress_bar(metadata.wasm_memory_size, "WASM memory"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.wasm_memory_size, + }, + "WASM memory", + ); download_blob_to_file( &agent, args.proxy, @@ -153,10 +170,10 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho metadata.wasm_memory_size, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("WASM memory: already complete"); } @@ -168,8 +185,12 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho .stable_memory .is_complete(metadata.stable_memory_size) { - let pb = - create_transfer_progress_bar(metadata.stable_memory_size, "Stable memory"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.stable_memory_size, + }, + "Stable memory", + ); download_blob_to_file( &agent, args.proxy, @@ -179,10 +200,10 @@ pub(crate) async fn exec(ctx: &Context, args: &DownloadArgs) -> Result<(), anyho metadata.stable_memory_size, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("Stable memory: already complete"); } diff --git a/crates/icp-cli/src/commands/canister/snapshot/upload.rs b/crates/icp-cli/src/commands/canister/snapshot/upload.rs index a8d97f2c4..874f030ae 100644 --- a/crates/icp-cli/src/commands/canister/snapshot/upload.rs +++ b/crates/icp-cli/src/commands/canister/snapshot/upload.rs @@ -5,16 +5,18 @@ use candid::Principal; use clap::{Args, ValueHint}; use icp::context::Context; use icp::prelude::*; +use icp_events::TaskKind; use serde::Serialize; use tracing::info; use super::SnapshotId; use crate::commands::args; +use crate::events::indicatif_reporter; use crate::operations::misc::format_timestamp; use crate::operations::snapshot_transfer::{ - BlobType, SnapshotPaths, SnapshotTransferError, UploadProgress, create_transfer_progress_bar, - delete_upload_progress, load_metadata, load_upload_progress, save_upload_progress, - upload_blob_from_file, upload_snapshot_metadata, upload_wasm_chunk, + BlobType, SnapshotPaths, SnapshotTransferError, UploadProgress, delete_upload_progress, + load_metadata, load_upload_progress, save_upload_progress, upload_blob_from_file, + upload_snapshot_metadata, upload_wasm_chunk, }; /// Upload a snapshot from local disk @@ -68,6 +70,11 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: let name = &args.cmd_args.canister; + // Transfer bars are drawn even under `--debug`, which is how they have always + // behaved: unlike the spinners, they carry the only indication that a long + // transfer is moving. + let transfers = indicatif_reporter(false); + // Open the snapshot directory with a lock let snapshot_dir = SnapshotPaths::new(args.input.clone())?; @@ -126,7 +133,12 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: // Upload WASM module if metadata.wasm_module_size > 0 { if progress.wasm_module_offset < metadata.wasm_module_size { - let pb = create_transfer_progress_bar(metadata.wasm_module_size, "WASM module"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.wasm_module_size, + }, + "WASM module", + ); upload_blob_from_file( &agent, args.proxy, @@ -135,10 +147,10 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: BlobType::WasmModule, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("WASM module: already complete"); } @@ -147,7 +159,12 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: // Upload WASM memory if metadata.wasm_memory_size > 0 { if progress.wasm_memory_offset < metadata.wasm_memory_size { - let pb = create_transfer_progress_bar(metadata.wasm_memory_size, "WASM memory"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.wasm_memory_size, + }, + "WASM memory", + ); upload_blob_from_file( &agent, args.proxy, @@ -156,10 +173,10 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: BlobType::WasmMemory, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("WASM memory: already complete"); } @@ -168,8 +185,12 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: // Upload stable memory if metadata.stable_memory_size > 0 { if progress.stable_memory_offset < metadata.stable_memory_size { - let pb = - create_transfer_progress_bar(metadata.stable_memory_size, "Stable memory"); + let task = transfers.task( + TaskKind::Bytes { + total: metadata.stable_memory_size, + }, + "Stable memory", + ); upload_blob_from_file( &agent, args.proxy, @@ -178,10 +199,10 @@ pub(crate) async fn exec(ctx: &Context, args: &UploadArgs) -> Result<(), anyhow: BlobType::StableMemory, paths, &mut progress, - &pb, + &task, ) .await?; - pb.finish_with_message("done"); + task.succeed("done"); } else { info!("Stable memory: already complete"); } diff --git a/crates/icp-cli/src/commands/deploy.rs b/crates/icp-cli/src/commands/deploy.rs index 0f38bafa8..a08722972 100644 --- a/crates/icp-cli/src/commands/deploy.rs +++ b/crates/icp-cli/src/commands/deploy.rs @@ -12,6 +12,7 @@ use icp::{ network::Configuration as NetworkConfiguration, }; use icp_canister_interfaces::candid_ui::MAINNET_CANDID_UI_CID; +use icp_events::TaskKind; use itertools::Itertools; use serde::Serialize; use std::collections::{BTreeMap, BTreeSet, HashSet}; @@ -24,7 +25,7 @@ use crate::{ events::indicatif_reporter, operations::{ binding_env_vars::set_binding_env_vars_many, - build::build_many_with_progress_bar, + build::build_many, candid_compat::check_candid_compatibility_many, create::{CreateFunding, CreateOperation, CreateTarget}, install::{install_many, resolve_install_mode_and_status}, @@ -33,7 +34,6 @@ use crate::{ sync::sync_many, }, options::{IdentityOpt, arg_struct_change_help}, - progress::{ProgressManager, ProgressManagerSettings}, }; /// Deploy a project to an environment @@ -183,12 +183,13 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: // Build the selected canisters info!("Building canisters:"); - build_many_with_progress_bar( + build_many( canisters_to_build, environment_selection.name(), ctx.builder.clone(), ctx.artifacts.clone(), &ctx.dirs.package_cache()?, + &indicatif_reporter(ctx.debug), ctx.debug, ) .await?; @@ -232,19 +233,17 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: existing_canisters.into_values().collect(), ); let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: ctx.debug }); + let reporter = indicatif_reporter(ctx.debug); for name in canisters_to_create.iter() { - let pb = progress_manager.create_progress_bar(name); - pb.set_message("Creating..."); + let task = reporter.task(TaskKind::Spinner, name.as_str()); + task.message("Creating..."); let create_op = create_operation.clone(); let (_, canister_info) = env.get_canister_info(name).map_err(|e| anyhow!(e))?; futs.push_back(async move { - ProgressManager::execute_with_custom_progress( - &pb, + task.run( create_op.create(&canister_info.settings.into()), || "Created successfully".to_string(), |err: &_| err.to_string(), - |_| false, ) .await }); @@ -499,6 +498,7 @@ pub(crate) async fn exec(ctx: &Context, args: &DeployArgs) -> Result<(), anyhow: env.network.name.clone(), canister_ids, args.proxy, + &indicatif_reporter(ctx.debug), ctx.debug, &pkg_cache, ) diff --git a/crates/icp-cli/src/commands/network/start.rs b/crates/icp-cli/src/commands/network/start.rs index f06942f22..fc8d3fe41 100644 --- a/crates/icp-cli/src/commands/network/start.rs +++ b/crates/icp-cli/src/commands/network/start.rs @@ -22,7 +22,9 @@ use icp::{ }; use tracing::{debug, info, warn}; -use crate::progress::{ProgressManager, ProgressManagerSettings}; +use icp_events::TaskKind; + +use crate::events::indicatif_reporter; use super::args::NetworkOrEnvironmentArgs; use icp::context::Context; @@ -191,14 +193,13 @@ pub(crate) async fn exec(ctx: &Context, args: &StartArgs) -> Result<(), anyhow:: } else { // The version is not fresh or not cached, download it debug!("Downloading icp-cli-network-launcher version `{version}`"); - let progress_manager = - ProgressManager::new(ProgressManagerSettings { hidden: debug }); - let pb = progress_manager.create_independent_progress_bar(); - pb.set_message(format!("Downloading icp-cli-network-launcher {version}...")); + let task = + indicatif_reporter(debug).unlabelled_task(TaskKind::Spinner); + task.message(format!("Downloading icp-cli-network-launcher {version}...")); let version_slot: Arc> = Arc::new(OnceLock::new()); let version_capture = version_slot.clone(); - let path = ProgressManager::execute_with_progress( - &pb, + let path = task + .run( async { let (ver, path) = download_launcher_version(pkg, version, &client).await?; @@ -211,7 +212,7 @@ pub(crate) async fn exec(ctx: &Context, args: &StartArgs) -> Result<(), anyhow:: }, |err| format!("Failed to download icp-cli-network-launcher: {err}"), ) - .await?; + .await?; Ok(Some(path)) } }) diff --git a/crates/icp-cli/src/commands/network/update.rs b/crates/icp-cli/src/commands/network/update.rs index 7ff1c0807..aa069ac7b 100644 --- a/crates/icp-cli/src/commands/network/update.rs +++ b/crates/icp-cli/src/commands/network/update.rs @@ -3,23 +3,23 @@ use std::sync::{Arc, OnceLock}; use clap::Parser; use icp::{context::Context, network::managed::cache::download_launcher_version}; -use crate::progress::{ProgressManager, ProgressManagerSettings}; +use icp_events::TaskKind; + +use crate::events::indicatif_reporter; /// Update icp-cli-network-launcher to the latest version. #[derive(Parser, Debug)] pub struct UpdateArgs {} pub async fn exec(ctx: &Context, _args: &UpdateArgs) -> Result<(), anyhow::Error> { - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: ctx.debug }); - let pb = progress_manager.create_independent_progress_bar(); - pb.set_message("Downloading latest icp-cli-network-launcher...".to_string()); + let task = indicatif_reporter(ctx.debug).unlabelled_task(TaskKind::Spinner); + task.message("Downloading latest icp-cli-network-launcher..."); let pkg = ctx.dirs.package_cache()?; let version_slot: Arc> = Arc::new(OnceLock::new()); let version_capture = version_slot.clone(); - ProgressManager::execute_with_progress( - &pb, + task.run( async move { pkg.with_write(async move |pkg| { let (ver, _path) = diff --git a/crates/icp-cli/src/commands/project/bundle.rs b/crates/icp-cli/src/commands/project/bundle.rs index b9217c0b8..664b67fba 100644 --- a/crates/icp-cli/src/commands/project/bundle.rs +++ b/crates/icp-cli/src/commands/project/bundle.rs @@ -3,7 +3,7 @@ use clap::{Args, ValueHint}; use icp::context::Context; use icp::prelude::*; -use crate::operations::bundle::create_bundle; +use crate::{events::indicatif_reporter, operations::bundle::create_bundle}; /// Bundle a project into a self-contained deployable archive. /// @@ -37,6 +37,7 @@ pub(crate) async fn exec(ctx: &Context, args: &BundleArgs) -> Result<(), anyhow: ctx.builder.clone(), ctx.artifacts.clone(), &ctx.dirs.package_cache()?, + &indicatif_reporter(ctx.debug), ctx.debug, &args.output, ) diff --git a/crates/icp-cli/src/commands/sync.rs b/crates/icp-cli/src/commands/sync.rs index ac2d1e099..244201a3c 100644 --- a/crates/icp-cli/src/commands/sync.rs +++ b/crates/icp-cli/src/commands/sync.rs @@ -10,6 +10,7 @@ use std::collections::BTreeMap; use tracing::info; use crate::{ + events::indicatif_reporter, operations::{proxy_management, sync::sync_many}, options::{EnvironmentOpt, IdentityOpt}, }; @@ -133,6 +134,7 @@ pub(crate) async fn exec(ctx: &Context, args: &SyncArgs) -> Result<(), anyhow::E env.network.name.clone(), canister_ids, args.proxy, + &indicatif_reporter(ctx.debug), ctx.debug, &pkg_cache, ) diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index dac83d53f..8d5c14c8b 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -1,32 +1,109 @@ //! Rendering [`icp_events`] onto the terminal. //! -//! [`IndicatifSink`] is the only place that knows both about events and about -//! `indicatif`. Operations emit events; this turns them into the same progress bars -//! the CLI has always drawn. The styles come from [`crate::progress`] so the two -//! renderers cannot drift apart while both exist. +//! This is the only module that knows about `indicatif`. Operations emit events; +//! [`IndicatifSink`] turns them into the progress bars the CLI has always drawn, and +//! the styles they are drawn in live here with it. use std::{ - collections::HashMap, + collections::{HashMap, VecDeque}, sync::{Arc, Mutex}, + time::Duration, }; use icp_events::{Event, EventSink, Outcome, Reporter, TaskId, TaskKind}; -use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget}; +use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget, ProgressStyle}; use itertools::Itertools; use tracing::debug; -use crate::progress::{ - RollingLines, STEADY_TICK, byte_style, failure_style, running_style, success_style, -}; - /// How many lines of a step's output stay on screen while it runs. const VISIBLE_STEP_LINES: usize = 4; +/// Animation frames for the spinner - creates a rotating star effect +const TICKS: &[&str] = &["✶", "✸", "✹", "✺", "✹", "✷"]; + +// Final tick symbols for different completion states +const TICK_EMPTY: &str = " "; +const TICK_SUCCESS: &str = "✔"; +const TICK_FAILURE: &str = "✘"; + +// Color schemes for different progress states +const COLOR_REGULAR: &str = "blue"; +const COLOR_SUCCESS: &str = "green"; +const COLOR_FAILURE: &str = "red"; + +/// How often a running spinner redraws itself. +const STEADY_TICK: Duration = Duration::from_millis(120); + +/// The style a spinner carries while it is still running. +fn running_style() -> ProgressStyle { + make_style(TICK_EMPTY, COLOR_REGULAR) +} + +/// The style a spinner carries once it has succeeded. +fn success_style() -> ProgressStyle { + make_style(TICK_SUCCESS, COLOR_SUCCESS) +} + +/// The style a spinner carries once it has failed. +fn failure_style() -> ProgressStyle { + make_style(TICK_FAILURE, COLOR_FAILURE) +} + +/// The style a byte-transfer bar carries. +fn byte_style() -> ProgressStyle { + ProgressStyle::default_bar() + .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") + .expect("invalid progress bar template") + .progress_chars("#>-") +} + +// Creates a progress bar style with a spinner that transitions to a final tick symbol +// - end_tick: the symbol to display when the progress completes (success, failure, etc.) +// - color: the color theme for the spinner and text +fn make_style(end_tick: &str, color: &str) -> ProgressStyle { + // Template format: "[prefix] [spinner] [message]" + let tmpl = format!("{{prefix}} {{spinner:.{color}}} {{msg}}"); + + ProgressStyle::with_template(&tmpl) + .expect("invalid style template") + // Combine animation frames with the final completion symbol + .tick_strings(&[TICKS, &[end_tick]].concat()) +} + +/// A fixed-capacity rolling buffer that always holds the last `capacity` items. +#[derive(Debug)] +struct RollingLines { + buf: VecDeque, + capacity: usize, +} + +impl RollingLines { + /// Create a new buffer with a fixed capacity. + fn new(capacity: usize) -> Self { + let buf = VecDeque::with_capacity(capacity); + Self { buf, capacity } + } + + /// Push a new line, evicting the oldest if full. + fn push(&mut self, line: String) { + if self.buf.len() == self.capacity { + self.buf.pop_front(); + } + + self.buf.push_back(line); + } + + /// Get an iterator over the current contents (in order). + fn iter(&self) -> impl Iterator { + self.buf.iter().map(|s| s.as_str()) + } +} + /// A [`Reporter`] that draws to the terminal. /// /// Each call site gets its own reporter — and so its own [`MultiProgress`] — which -/// matches how `ProgressManager` was used: bars belonging to one operation are -/// grouped, and the group is torn down when the operation returns. +/// matches how the progress manager it replaced was used: bars belonging to one +/// operation are grouped, and the group is torn down when the operation returns. pub(crate) fn indicatif_reporter(hidden: bool) -> Reporter { Reporter::new(Arc::new(IndicatifSink::new(hidden))) } @@ -236,19 +313,18 @@ impl EventSink for IndicatifSink { } } -/// Proof that the events path draws what `ProgressManager` drew. +/// Proof that the events path draws what the code it replaced drew. /// -/// Both renderers are pointed at the same recording terminal and driven through the -/// same logical sequence; the frames they emit are then compared byte for byte. This -/// is what backs the claim that converting the four operations left the visible CLI -/// output unchanged. +/// The pre-inversion renderers — `progress::ProgressManager` and +/// `snapshot_transfer::create_transfer_progress_bar` — are deleted in the same change +/// that adds this, so there is nothing left to compare against at runtime. Instead, +/// every `EXPECTED_*` below is the literal output those renderers produced, captured +/// from them before they were removed by pointing them at the same [`RecordingTerm`] +/// and driving them through the same logical sequence. A frame that changes here is a +/// frame that changed for the user. #[cfg(test)] -mod rendering_equivalence { +mod rendering { use super::*; - use crate::{ - operations::snapshot_transfer::create_transfer_progress_bar, - progress::{ProgressManager, ProgressManagerSettings}, - }; use futures::executor::block_on; use indicatif::TermLike; use std::io; @@ -268,10 +344,16 @@ mod rendering_equivalence { /// marker and the resulting consecutive duplicates removed. /// /// What survives is the sequence of *states* a bar passed through — prefix, - /// message, and final tick — which is exactly what has to match. Two things are - /// dropped on the way: the blank line indicatif writes to pad out the rest of - /// the terminal row, which is a function of the frame it follows, and the - /// animation glyph, which advances on a timer and so differs run to run. + /// message, and final tick — which is exactly what has to match. Three things + /// are dropped on the way: + /// + /// - the blank line indicatif writes to pad out the rest of the terminal row, + /// which is a function of the frame it follows; + /// - the animation glyph, which advances on a timer and so differs run to run; + /// - a spinner frame with no message yet, which is the animation thread + /// getting a frame in before the operation has said anything. Whether that + /// happens is scheduling, not behaviour: the frame is overwritten by the + /// next one either way. pub(super) fn frames(&self) -> Vec { let mut frames: Vec = self .writes @@ -289,12 +371,32 @@ mod rendering_equivalence { c } }) - .collect() + .collect::() }) + .filter(|frame| !frame.trim_end().ends_with('~')) .collect(); frames.dedup(); frames } + + /// Every frame drawn, untouched apart from dropping the blank padding lines. + pub(super) fn raw_frames(&self) -> Vec { + self.writes + .lock() + .expect("writes poisoned") + .iter() + .filter(|frame| !frame.trim().is_empty()) + .cloned() + .collect() + } + + /// [`frames`](Self::frames), with everything clock-derived blanked out, for + /// the byte bar. + pub(super) fn timeless_frames(&self) -> Vec { + let mut frames: Vec = self.frames().iter().map(mask_timings).collect(); + frames.dedup(); + frames + } } impl TermLike for RecordingTerm { @@ -347,43 +449,14 @@ mod rendering_equivalence { ProgressDrawTarget::term_like(Box::new(term.clone())) } - fn old_manager(term: &RecordingTerm) -> ProgressManager { - let manager = ProgressManager::new(ProgressManagerSettings { hidden: false }); - manager - .multi_progress - .set_draw_target(recording_target(term)); - manager - } - fn new_reporter(term: &RecordingTerm) -> Reporter { Reporter::new(Arc::new(IndicatifSink::with_draw_target(recording_target( term, )))) } - /// Every frame `ProgressManager` drew for one canister's outcome. - fn old_frames( - result: Result<(), E>, - success: &str, - error: impl Fn(&E) -> String, - ) -> Vec { - let term = RecordingTerm::default(); - let manager = old_manager(&term); - - let bar = manager.create_progress_bar("backend"); - bar.set_message("Installing..."); - let _ = block_on(ProgressManager::execute_with_progress( - &bar, - async { result }, - || success.to_string(), - error, - )); - - term.frames() - } - - /// Every frame the event stream draws for the same outcome. - fn new_frames( + /// Every frame the event stream draws for one canister's outcome. + fn frames_for( result: Result<(), E>, success: &str, error: impl Fn(&E) -> String, @@ -398,119 +471,147 @@ mod rendering_equivalence { term.frames() } - #[test] - fn a_success_draws_the_same_frames_as_before() { - let old = old_frames::(Ok(()), "Installed successfully", |e| e.clone()); - let new = new_frames::(Ok(()), "Installed successfully", |e| e.clone()); + /// What `ProgressManager` drew for a canister that installed successfully. + const EXPECTED_SUCCESS: [&str; 3] = [ + "[backend] ~ Installing...", + "[backend] ~ Installed successfully", + "[backend] ✔ Installed successfully", + ]; - assert!( - old.iter().any(|f| f.contains("Installed successfully")), - "old frames: {old:?}" + #[test] + fn a_success_draws_the_frames_the_progress_manager_drew() { + assert_eq!( + frames_for::(Ok(()), "Installed successfully", |e| e.clone()), + EXPECTED_SUCCESS ); - assert_eq!(old, new); } + /// What `ProgressManager` drew for a canister that failed to install. + const EXPECTED_FAILURE: [&str; 3] = [ + "[backend] ~ Installing...", + "[backend] ~ Failed to install canister: boom", + "[backend] ✘ Failed to install canister: boom", + ]; + #[test] - fn a_failure_draws_the_same_frames_as_before() { + fn a_failure_draws_the_frames_the_progress_manager_drew() { let message = "Failed to install canister: boom"; - let old = old_frames(Err("boom".to_string()), "unused", |_| message.to_string()); - let new = new_frames(Err("boom".to_string()), "unused", |_| message.to_string()); - assert!( - old.iter().any(|f| f.contains(message)), - "old frames: {old:?}" + assert_eq!( + frames_for(Err("boom".to_string()), "unused", |_| message.to_string()), + EXPECTED_FAILURE ); - assert_eq!(old, new); } /// `candid_compat` skipped a canister with `finish_with_message`, which left the /// running style in place and drew a single frame. A neutral finish has to do the /// same, down to not slipping in an extra redraw. #[test] - fn a_skip_draws_the_same_frames_as_finish_with_message() { - let term = RecordingTerm::default(); - old_manager(&term) - .create_progress_bar("backend") - .finish_with_message("Skipped (not an upgrade)"); - let old = term.frames(); - + fn a_skip_draws_what_finish_with_message_drew() { let term = RecordingTerm::default(); new_reporter(&term) .task(TaskKind::Spinner, "backend") .skip("Skipped (not an upgrade)"); - let new = term.frames(); - assert!( - old.iter().any(|f| f.contains("Skipped (not an upgrade)")), - "old frames: {old:?}" - ); - assert_eq!(old, new); + assert_eq!(term.frames(), ["[backend] Skipped (not an upgrade)"]); } - /// Every frame `create_transfer_progress_bar` — the pre-inversion byte bar, still used - /// by `canister snapshot download`/`upload` — draws at `position`. - fn old_byte_frames(position: u64) -> Vec { + /// Several canisters share one `MultiProgress`, so their bars have to be added in + /// the same order to land on the same lines. + #[test] + fn bars_are_drawn_in_the_order_the_canisters_were_given() { let term = RecordingTerm::default(); - let bar = create_transfer_progress_bar(100, "WASM module"); - bar.set_draw_target(recording_target(&term)); - bar.set_position(position); - bar.tick(); + let reporter = new_reporter(&term); + for name in ["frontend", "backend"] { + reporter.task(TaskKind::Spinner, name).skip("done"); + } - term.frames() + assert_eq!(term.frames(), ["[frontend] done", "[backend] done"]); } - /// Every frame a `TaskKind::Bytes` task draws at the same position. - fn new_byte_frames(position: u64) -> Vec { + /// Every frame a [`TaskKind::Bytes`] task draws, with the clock blanked out. + fn byte_frames(positions: &[u64], finish: bool) -> Vec { let term = RecordingTerm::default(); let reporter = new_reporter(&term); let task = reporter.task(TaskKind::Bytes { total: 100 }, "WASM module"); - task.position(position); + for position in positions { + task.position(*position); + } + if finish { + task.succeed("done"); + return term.timeless_frames(); + } - term.frames() + // Read the frames while the task is still alive: finishing a byte bar fills it + // to its length, and an unfinished transfer has not got there yet. + term.timeless_frames() } - /// The byte shape is still drawn the pre-inversion way by - /// `snapshot_transfer::create_transfer_progress_bar`. Both sides take their template - /// from `progress::byte_style`, and this pins that they stay interchangeable. + /// The line `create_transfer_progress_bar` drew for a transfer at rest. /// - /// Compared at rest, where the rate reads `0 B/s` on both sides: `{wide_bar}` is given - /// whatever width the rest of the line leaves over, so once a transfer is under way the - /// bar's own width is a function of how long the rate string happens to be. + /// `{wide_bar}` is given whatever width the rest of the line leaves over, so the + /// bar's own width is a function of how long the rate string happens to be — hence + /// comparing at rest, where the rate reads `0 B/s` either way. #[test] - fn a_byte_task_draws_the_same_line_as_the_transfer_bar() { - let old = old_byte_frames(0); - let new = new_byte_frames(0); - - assert!( - old.last() - .is_some_and(|frame| frame.contains("WASM module") && frame.contains("0 B/100 B")), - "old frames: {old:?}" - ); + fn a_byte_task_draws_the_transfer_bars_line() { assert_eq!( - old.last().map(|frame| mask_timings(frame)), - new.last().map(|frame| mask_timings(frame)), - "old: {old:?}\nnew: {new:?}" + byte_frames(&[0], false).first().map(String::as_str), + Some("WASM module [??:??:??] [---------------------------------] 0 B/100 B ") ); } /// `progress_chars` is the part of the byte template the at-rest comparison above /// cannot see, since nothing is filled in yet. + /// + /// Only the glyphs are pinned, not how many of each: `{wide_bar}` takes whatever + /// width the rest of the line leaves over, and once bytes have moved that includes + /// a transfer rate whose text is as long as the machine happened to be fast. #[test] - fn both_byte_bars_fill_with_the_same_glyphs() { - for frames in [old_byte_frames(64), new_byte_frames(64)] { - let drawn = frames.last().expect("nothing was drawn"); - - assert!( - drawn.contains('#') && drawn.contains('>') && drawn.contains('-'), - "{drawn:?}" - ); - } + fn a_byte_task_fills_with_the_transfer_bars_glyphs() { + let drawn = byte_frames(&[64], false).pop().expect("nothing was drawn"); + + assert!( + drawn.contains("WASM module") + && drawn.contains("64 B/100 B") + && drawn.contains('#') + && drawn.contains('>') + && drawn.contains('-'), + "{drawn:?}" + ); + } + + /// A resumed transfer starts partway in: `snapshot_transfer` reports the frontier + /// it recovered from disk before reporting any new bytes, so the bar opens at that + /// offset instead of counting up from zero. Its last frame is full, because + /// finishing a byte bar completes it. + #[test] + fn a_resumed_byte_task_starts_from_its_offset() { + assert_eq!( + byte_counters(&byte_frames(&[40, 72], true)), + ["40 B/100 B", "72 B/100 B", "100 B/100 B"] + ); + } + + /// The `/` counter of each frame, which — unlike the width of the bar + /// beside it — does not depend on how fast the transfer went. + fn byte_counters(frames: &[String]) -> Vec { + frames + .iter() + .map(|frame| { + let after_bar = frame + .rsplit_once(']') + .expect("a byte frame always draws its bar") + .1; + after_bar.trim().to_owned() + }) + .collect() } /// Blank out the parts of a byte bar that are derived from wall-clock time: the /// `[HH:MM:SS]` elapsed counter and the trailing `(rate, eta)`. - fn mask_timings(frame: &str) -> String { + fn mask_timings(frame: impl AsRef) -> String { + let frame = frame.as_ref(); let mut out = String::with_capacity(frame.len()); let mut rest = frame; @@ -545,36 +646,12 @@ mod rendering_equivalence { _ => c.is_ascii_digit(), }) } - - /// Several canisters share one `MultiProgress`, so their bars have to be added in - /// the same order to land on the same lines. - #[test] - fn bars_are_drawn_in_the_order_the_canisters_were_given() { - let term = RecordingTerm::default(); - let manager = old_manager(&term); - for name in ["frontend", "backend"] { - manager - .create_progress_bar(name) - .finish_with_message("done"); - } - let old = term.frames(); - - let term = RecordingTerm::default(); - let reporter = new_reporter(&term); - for name in ["frontend", "backend"] { - reporter.task(TaskKind::Spinner, name).skip("done"); - } - let new = term.frames(); - - assert!(!old.is_empty()); - assert_eq!(old, new); - } } #[cfg(test)] mod tests { use super::{ - rendering_equivalence::{RecordingTerm, recording_target}, + rendering::{RecordingTerm, recording_target}, *, }; @@ -785,7 +862,9 @@ mod tests { }); std::thread::sleep(STEADY_TICK * 3); - let frames = term.frames(); + // Raw frames, not the normalized ones: the point is that no frame was ever + // drawn without the label, including the message-less ones. + let frames = term.raw_frames(); assert!(!frames.is_empty(), "the ticker never drew anything"); assert!( frames.iter().all(|frame| frame.contains("[backend]")), diff --git a/crates/icp-cli/src/main.rs b/crates/icp-cli/src/main.rs index dea176d80..2fdd6493a 100644 --- a/crates/icp-cli/src/main.rs +++ b/crates/icp-cli/src/main.rs @@ -21,7 +21,6 @@ mod events; mod logging; pub(crate) mod operations; mod options; -mod progress; mod telemetry; mod version; diff --git a/crates/icp-cli/src/operations/build.rs b/crates/icp-cli/src/operations/build.rs index eb85c7bb5..2f1287045 100644 --- a/crates/icp-cli/src/operations/build.rs +++ b/crates/icp-cli/src/operations/build.rs @@ -8,10 +8,14 @@ use icp::{ package::PackageCache, prelude::*, }; +use icp_events::{Reporter, Task, TaskKind}; use snafu::{ResultExt, Snafu}; use tracing::error; -use crate::progress::{MultiStepProgressBar, ProgressManager, ProgressManagerSettings}; +use crate::operations::step_replay::replay; + +/// What a build task's output is called when it is replayed after a failure. +const OUTPUT_LABEL: &str = "Build"; #[derive(Debug, Snafu)] pub enum BuildOperationError { @@ -43,14 +47,14 @@ pub struct BuildManyError { struct BuildFailure { canister_name: String, error: BuildOperationError, - progress_output: Vec, + step_output: Vec, } pub(crate) async fn build( canister_path: &Path, canister: &Canister, environment: &str, - pb: &mut MultiStepProgressBar, + task: &mut Task, builder: Arc, artifacts: Arc, pkg_cache: &PackageCache, @@ -61,8 +65,9 @@ pub(crate) async fn build( let step_count = canister.build.steps.len(); for (i, step) in canister.build.steps.iter().enumerate() { let current_step = i + 1; - let pb_hdr = format!("Building: step {current_step} of {step_count} {step}"); - let tx = pb.begin_step(pb_hdr); + task.begin_step(format!( + "Building: step {current_step} of {step_count} {step}" + )); let build_result = builder .build( @@ -72,12 +77,12 @@ pub(crate) async fn build( output: wasm_output_path.to_owned(), environment: environment.to_owned(), }, - Some(tx), + Some(task.output()), pkg_cache, ) .await; - pb.end_step().await; + task.end_step(); build_result?; } @@ -96,19 +101,30 @@ pub(crate) async fn build( Ok(()) } -pub(crate) async fn build_many_with_progress_bar( +/// Builds several canisters, reporting each one's steps and their output. +/// +/// `all_step_output` replays every step of a failed build rather than just the one +/// that failed, which is what `--debug` asks for. +pub(crate) async fn build_many( canisters: Vec<(PathBuf, Canister)>, environment: &str, builder: Arc, artifacts: Arc, pkg_cache: &PackageCache, - debug: bool, + reporter: &Reporter, + all_step_output: bool, ) -> Result<(), BuildManyError> { let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: debug }); for (canister_path, canister) in canisters { - let mut pb = progress_manager.create_multi_step_progress_bar(&canister.name, "Build"); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let mut task = reporter.task( + TaskKind::Steps { + output_label: OUTPUT_LABEL.to_owned(), + }, + canister.name.as_str(), + ); let builder = builder.clone(); let artifacts = artifacts.clone(); let fut = async move { @@ -116,27 +132,37 @@ pub(crate) async fn build_many_with_progress_bar( &canister_path, &canister, environment, - &mut pb, + &mut task, builder, artifacts, pkg_cache, ) .await; - // Execute with progress tracking for final state - let result = ProgressManager::execute_with_progress( - &pb, - async { build_result }, - || "Built successfully".to_string(), - |err| format!("Failed to build canister: {err}"), - ) - .await; + // Read the steps back before the task is consumed, and only when there is + // a failure to explain. + let step_output = build_result.as_ref().err().map(|_| { + replay( + &canister.name, + OUTPUT_LABEL, + &task.recorded_steps(), + all_step_output, + ) + }); + + let result = task + .run( + async { build_result }, + || "Built successfully".to_string(), + |err| format!("Failed to build canister: {err}"), + ) + .await; // Map error to include canister context for deferred printing result.map_err(|error| BuildFailure { canister_name: canister.name.clone(), error, - progress_output: pb.dump_output(debug), + step_output: step_output.unwrap_or_default(), }) }; futs.push_back(fut); @@ -158,7 +184,7 @@ pub(crate) async fn build_many_with_progress_bar( failure.canister_name, ); error!("'{}'", failure.error); - for line in &failure.progress_output { + for line in &failure.step_output { error!("{line}"); } } @@ -174,3 +200,170 @@ pub(crate) async fn build_many_with_progress_bar( Ok(()) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{ + EmptyArtifacts, bare_canister, recording_reporter, task_labels, + }; + use icp::manifest::{BuildStep, script}; + use icp_events::{Event, Outcome, TaskId}; + + fn pkg_cache() -> (camino_tempfile::Utf8TempDir, PackageCache) { + let dir = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + let cache = PackageCache::new(dir.path().to_owned()).expect("package cache"); + (dir, cache) + } + + /// A canister with one script step that prints a line and writes the wasm the + /// build then looks for. + fn canister_printing(name: &str, line: &str) -> Canister { + let mut canister = bare_canister(name); + canister.build.steps = vec![BuildStep::Script(script::Adapter { + command: script::CommandField::Command(format!( + r#"echo {line} && echo wasm > "$ICP_WASM_OUTPUT_PATH""# + )), + })]; + canister + } + + /// A canister whose one script step fails. + fn canister_failing(name: &str) -> Canister { + let mut canister = bare_canister(name); + canister.build.steps = vec![BuildStep::Script(script::Adapter { + command: script::CommandField::Command("echo doomed && exit 3".to_owned()), + })]; + canister + } + + /// The whole shape of a build, reported: the task, its step, the output the step + /// produced, and how it ended. + #[tokio::test] + async fn a_build_reports_its_steps_and_their_output() { + let (reporter, sink) = recording_reporter(); + let (_dir, cache) = pkg_cache(); + let out = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + + build_many( + vec![(out.path().to_owned(), canister_printing("backend", "hello"))], + "local", + Arc::new(icp::canister::build::Builder), + Arc::new(EmptyArtifacts), + &cache, + &reporter, + false, + ) + .await + .expect("build should succeed"); + + let events = sink.events(); + assert_eq!( + events.first().unwrap(), + &Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Build".to_owned() + }, + label: Some("backend".to_owned()), + } + ); + assert!( + events.iter().any(|event| matches!( + event, + Event::StepStarted { id, index: 0, title } + if *id == TaskId(0) && title.starts_with("Building: step 1 of 1") + )), + "{events:?}" + ); + assert!(events.contains(&Event::StepOutput { + id: TaskId(0), + line: "hello".to_owned(), + })); + assert_eq!( + events.last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some("Built successfully".to_owned()), + } + ); + } + + /// A failing step is reported as a failure, and its output is available for the + /// replay that follows. + #[tokio::test] + async fn a_failed_build_reports_the_failure_and_keeps_its_output() { + let (reporter, sink) = recording_reporter(); + let (_dir, cache) = pkg_cache(); + let out = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + + let err = build_many( + vec![(out.path().to_owned(), canister_failing("backend"))], + "local", + Arc::new(icp::canister::build::Builder), + Arc::new(EmptyArtifacts), + &cache, + &reporter, + false, + ) + .await + .expect_err("build should fail"); + assert!(err.to_string().contains("backend")); + + let events = sink.events(); + assert!(events.contains(&Event::StepOutput { + id: TaskId(0), + line: "doomed".to_owned(), + })); + let Event::TaskFinished { + outcome, message, .. + } = events.last().unwrap().clone() + else { + panic!("a build always finishes its task: {events:?}"); + }; + assert_eq!(outcome, Outcome::Failure); + assert!( + message + .as_deref() + .is_some_and(|m| m.starts_with("Failed to build canister:")), + "{message:?}" + ); + } + + /// Tasks appear in the order the canisters were given, whichever order their + /// builds happen to finish in. + #[tokio::test] + async fn tasks_are_started_in_the_order_the_canisters_were_given() { + let (reporter, sink) = recording_reporter(); + let (_dir, cache) = pkg_cache(); + let out = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + + let canisters = vec![ + ( + out.path().to_owned(), + canister_printing("frontend", "first"), + ), + ( + out.path().to_owned(), + canister_printing("backend", "second"), + ), + ]; + build_many( + canisters, + "local", + Arc::new(icp::canister::build::Builder), + Arc::new(EmptyArtifacts), + &cache, + &reporter, + false, + ) + .await + .expect("build should succeed"); + + assert_eq!( + task_labels(&sink.events()), + vec![Some("frontend".to_owned()), Some("backend".to_owned())] + ); + } +} diff --git a/crates/icp-cli/src/operations/bundle.rs b/crates/icp-cli/src/operations/bundle.rs index 6786fc7d5..cdab030ba 100644 --- a/crates/icp-cli/src/operations/bundle.rs +++ b/crates/icp-cli/src/operations/bundle.rs @@ -28,7 +28,9 @@ use icp::{ use snafu::{OptionExt, ResultExt, Snafu}; use tar::Builder; -use crate::operations::build::{BuildManyError, build_many_with_progress_bar}; +use icp_events::Reporter; + +use crate::operations::build::{BuildManyError, build_many}; #[derive(Debug, Snafu)] pub enum BundleError { @@ -328,7 +330,8 @@ pub(crate) async fn create_bundle( builder: Arc, artifacts: Arc, pkg_cache: &PackageCache, - debug: bool, + reporter: &Reporter, + all_step_output: bool, output: &Path, ) -> Result<(), BundleError> { // A bundle mirrors the workspace: the root project at the archive root and @@ -347,13 +350,14 @@ pub(crate) async fn create_bundle( validate_env_var_files(&canisters, &canonical_project_dir)?; validate_output_path(output, &canonical_sync_dirs)?; - build_many_with_progress_bar( + build_many( canisters.clone(), environment, builder, artifacts.clone(), pkg_cache, - debug, + reporter, + all_step_output, ) .await?; diff --git a/crates/icp-cli/src/operations/mod.rs b/crates/icp-cli/src/operations/mod.rs index 4a1bd66ab..7aabba21c 100644 --- a/crates/icp-cli/src/operations/mod.rs +++ b/crates/icp-cli/src/operations/mod.rs @@ -10,6 +10,7 @@ pub(crate) mod proxy_management; pub(crate) mod recover_cycles; pub(crate) mod settings; pub(crate) mod snapshot_transfer; +pub(crate) mod step_replay; pub(crate) mod sync; pub(crate) mod token; diff --git a/crates/icp-cli/src/operations/snapshot_transfer.rs b/crates/icp-cli/src/operations/snapshot_transfer.rs index 6f7f31ad5..335cc28fd 100644 --- a/crates/icp-cli/src/operations/snapshot_transfer.rs +++ b/crates/icp-cli/src/operations/snapshot_transfer.rs @@ -15,12 +15,11 @@ use ic_management_canister_types::{ use super::proxy::UpdateOrProxyError; use super::proxy_management; -use crate::progress::byte_style; use icp::{ fs::lock::{DirectoryStructureLock, LWrite, LockError, PathsAccess}, prelude::*, }; -use indicatif::ProgressBar; +use icp_events::Task; use serde::{Deserialize, Serialize}; use snafu::{ResultExt, Snafu}; use tokio::{ @@ -425,14 +424,6 @@ where } } -/// Create a progress bar for byte transfers. -pub fn create_transfer_progress_bar(total_bytes: u64, label: &str) -> ProgressBar { - let pb = ProgressBar::new(total_bytes); - pb.set_style(byte_style()); - pb.set_prefix(label.to_string()); - pb -} - /// Read snapshot metadata from a canister. pub async fn read_snapshot_metadata( agent: &Agent, @@ -509,7 +500,7 @@ pub async fn download_blob_to_file( total_size: u64, paths: LWrite<&SnapshotPaths>, progress: &mut DownloadProgress, - progress_bar: &ProgressBar, + task: &Task, ) -> Result<(), SnapshotTransferError> { let output_path = paths.blob_path(blob_type); @@ -541,9 +532,9 @@ pub async fn download_blob_to_file( f }; - // Set initial progress based on frontier + // Set initial progress based on frontier: a resumed download starts partway in. let initial_bytes = progress.blob_progress(blob_type).frontier; - progress_bar.set_position(initial_bytes); + task.position(initial_bytes); // Determine which chunks need downloading let snapshot_id_vec = snapshot_id.to_vec(); @@ -607,8 +598,8 @@ pub async fn download_blob_to_file( .mark_complete(chunk_offset, total_size); save_download_progress(progress, paths)?; - // Update progress bar to show frontier position - progress_bar.set_position(progress.blob_progress(blob_type).frontier); + // Report the frontier position + task.position(progress.blob_progress(blob_type).frontier); } Ok(()) @@ -659,7 +650,7 @@ pub async fn upload_blob_from_file( blob_type: BlobType, paths: LWrite<&SnapshotPaths>, progress: &mut UploadProgress, - progress_bar: &ProgressBar, + task: &Task, ) -> Result { let input_path = paths.blob_path(blob_type); let file_size = std::fs::metadata(&input_path) @@ -686,7 +677,8 @@ pub async fn upload_blob_from_file( .context(SeekBlobFileSnafu { path: &input_path })?; } - progress_bar.set_position(start_offset); + // A resumed upload starts partway in. + task.position(start_offset); // Read all chunks and launch uploads concurrently let snapshot_id_vec = snapshot_id.to_vec(); @@ -738,7 +730,7 @@ pub async fn upload_blob_from_file( while let Some(&size) = completed.get(&next_report_offset) { completed.remove(&next_report_offset); next_report_offset += size; - progress_bar.set_position(next_report_offset); + task.position(next_report_offset); // Update and save progress match blob_type { diff --git a/crates/icp-cli/src/operations/step_replay.rs b/crates/icp-cli/src/operations/step_replay.rs new file mode 100644 index 000000000..3b2020a57 --- /dev/null +++ b/crates/icp-cli/src/operations/step_replay.rs @@ -0,0 +1,133 @@ +//! Replaying the output of a task's steps after it has failed. +//! +//! While a step runs, only the tail of its output is on screen, and the bar draws +//! over it as it goes. When the operation fails, that view is gone but the output is +//! the whole explanation — so the recorded steps are formatted back out, once every +//! bar has been closed, and printed as errors. + +use icp_events::RecordedStep; + +/// Format a failed task's captured output for printing. +/// +/// `all_steps` replays the whole run rather than just the step that failed, which is +/// what `--debug` asks for. Every line is prefixed with the canister name, since +/// several canisters fail into the same output. +pub(crate) fn replay( + canister_name: &str, + output_label: &str, + steps: &[RecordedStep], + all_steps: bool, +) -> Vec { + let mut lines = vec![format!("[{canister_name}] {output_label} output:")]; + + let steps = if all_steps { + steps + } else { + steps.last().map(std::slice::from_ref).unwrap_or_default() + }; + + for step in steps { + // Step titles are multi-line — the header the bar showed, plus the rolling + // output frame around it — so only the parts with something on them are kept. + for line in step.title.lines() { + if !line.is_empty() { + lines.push(format!("[{canister_name}] {line}:")); + } + } + + if step.lines.is_empty() { + lines.push(format!("[{canister_name}] ")); + } else { + lines.extend( + step.lines + .iter() + .map(|line| format!("[{canister_name}] > {line}")), + ); + } + } + + lines +} + +#[cfg(test)] +mod tests { + use super::*; + + fn step(title: &str, lines: &[&str]) -> RecordedStep { + RecordedStep { + title: title.to_owned(), + lines: lines.iter().map(|l| (*l).to_owned()).collect(), + } + } + + #[test] + fn only_the_failing_step_is_replayed_by_default() { + let steps = [step("step 1", &["ok"]), step("step 2", &["boom"])]; + + assert_eq!( + replay("backend", "Build", &steps, false), + vec![ + "[backend] Build output:", + "[backend] step 2:", + "[backend] > boom", + ] + ); + } + + #[test] + fn every_step_is_replayed_when_asked_for() { + let steps = [step("step 1", &["ok"]), step("step 2", &["boom"])]; + + assert_eq!( + replay("backend", "Build", &steps, true), + vec![ + "[backend] Build output:", + "[backend] step 1:", + "[backend] > ok", + "[backend] step 2:", + "[backend] > boom", + ] + ); + } + + /// A step that printed nothing says so, rather than trailing off. + #[test] + fn a_silent_step_is_called_out() { + assert_eq!( + replay("backend", "Sync", &[step("step 1", &[])], false), + vec![ + "[backend] Sync output:", + "[backend] step 1:", + "[backend] " + ] + ); + } + + /// Sync titles start with a newline, and a step's title carries the frame the + /// bar drew around its output; neither should show up as an empty line. + #[test] + fn blank_title_lines_are_dropped() { + assert_eq!( + replay( + "backend", + "Sync", + &[step("\nSyncing: a 1 of 1\n", &["done"])], + false + ), + vec![ + "[backend] Sync output:", + "[backend] Syncing: a 1 of 1:", + "[backend] > done", + ] + ); + } + + /// Nothing ran, so there is nothing to replay but the header. + #[test] + fn no_steps_replays_only_the_header() { + assert_eq!( + replay("backend", "Build", &[], false), + vec!["[backend] Build output:"] + ); + } +} diff --git a/crates/icp-cli/src/operations/sync.rs b/crates/icp-cli/src/operations/sync.rs index 18c77efcc..64c637122 100644 --- a/crates/icp-cli/src/operations/sync.rs +++ b/crates/icp-cli/src/operations/sync.rs @@ -7,12 +7,16 @@ use icp::{ package::PackageCache, prelude::PathBuf, }; +use icp_events::{Reporter, Task, TaskKind}; use snafu::prelude::*; use std::collections::BTreeMap; use std::sync::Arc; use tracing::error; -use crate::progress::{MultiStepProgressBar, ProgressManager, ProgressManagerSettings}; +use crate::operations::step_replay::replay; + +/// What a sync task's output is called when it is replayed after a failure. +const OUTPUT_LABEL: &str = "Sync"; #[derive(Debug, Snafu)] #[snafu(display("Canister(s) {names:?} failed to sync."))] @@ -25,10 +29,11 @@ struct SyncFailure { canister_name: String, canister_id: Principal, error: SynchronizeError, - progress_output: Vec, + step_output: Vec, } /// Synchronizes a single canister using its configured sync steps +#[allow(clippy::too_many_arguments)] async fn sync_canister( syncer: &Arc, agent: &Agent, @@ -39,7 +44,7 @@ async fn sync_canister( network: &str, canister_ids: &BTreeMap, proxy: Option, - pb: &mut MultiStepProgressBar, + task: &mut Task, pkg_cache: &PackageCache, ) -> Result, SynchronizeError> { let step_count = canister_info.sync.steps.len(); @@ -48,9 +53,7 @@ async fn sync_canister( for (i, step) in canister_info.sync.steps.iter().enumerate() { // Indicate to user the current step being executed let current_step = i + 1; - let pb_hdr = format!("\nSyncing: {step} {current_step} of {step_count}"); - - let tx = pb.begin_step(pb_hdr); + task.begin_step(format!("\nSyncing: {step} {current_step} of {step_count}")); // Execute step let sync_result = syncer @@ -65,13 +68,12 @@ async fn sync_canister( proxy, }, agent, - Some(tx), + Some(task.output()), pkg_cache, ) .await; - // Ensure background receiver drains all messages - pb.end_step().await; + task.end_step(); stderr_lines.extend(sync_result?); } @@ -79,7 +81,11 @@ async fn sync_canister( Ok(stderr_lines) } -/// Orchestrates syncing multiple canisters with progress tracking +/// Orchestrates syncing multiple canisters, reporting each one's steps. +/// +/// `all_step_output` replays every step of a failed sync rather than just the one +/// that failed, which is what `--debug` asks for. +#[allow(clippy::too_many_arguments)] pub(crate) async fn sync_many( syncer: Arc, agent: Agent, @@ -88,14 +94,21 @@ pub(crate) async fn sync_many( network: String, canister_ids: BTreeMap, proxy: Option, - debug: bool, + reporter: &Reporter, + all_step_output: bool, pkg_cache: &PackageCache, ) -> Result<(), SyncOperationError> { let mut futs = FuturesOrdered::new(); - let progress_manager = ProgressManager::new(ProgressManagerSettings { hidden: debug }); for (cid, canister_path, canister_info) in canisters { - let mut pb = progress_manager.create_multi_step_progress_bar(&canister_info.name, "Sync"); + // Started up front so the tasks appear in the order the canisters were given, + // regardless of the order the futures below are first polled in. + let mut task = reporter.task( + TaskKind::Steps { + output_label: OUTPUT_LABEL.to_owned(), + }, + canister_info.name.as_str(), + ); let fut = { let agent = agent.clone(); @@ -116,19 +129,29 @@ pub(crate) async fn sync_many( &network, &canister_ids, proxy, - &mut pb, + &mut task, pkg_cache, ) .await; - // Execute with progress tracking for final state - let result = ProgressManager::execute_with_progress( - &pb, - async { sync_result }, - || format!("Synced successfully: {cid}"), - |err| format!("Failed to sync canister: {err}"), - ) - .await; + // Read the steps back before the task is consumed, and only when there + // is a failure to explain. + let step_output = sync_result.as_ref().err().map(|_| { + replay( + &canister_info.name, + OUTPUT_LABEL, + &task.recorded_steps(), + all_step_output, + ) + }); + + let result = task + .run( + async { sync_result }, + || format!("Synced successfully: {cid}"), + |err| format!("Failed to sync canister: {err}"), + ) + .await; // Print stderr lines the plugin emitted; the rolling buffer // discards them on success, but they belong on the persistent @@ -144,7 +167,7 @@ pub(crate) async fn sync_many( canister_name: canister_info.name.clone(), canister_id: cid, error, - progress_output: pb.dump_output(debug), + step_output: step_output.unwrap_or_default(), }) } }; @@ -176,7 +199,7 @@ pub(crate) async fn sync_many( cause = err.source(); } } - for line in &failure.progress_output { + for line in &failure.step_output { error!("{line}"); } } @@ -192,3 +215,200 @@ pub(crate) async fn sync_many( Ok(()) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{bare_canister, recording_reporter, unreachable_agent}; + use async_trait::async_trait; + use icp::canister::sync::{Syncer, script::ScriptRunner}; + use icp::manifest::{SyncStep, script}; + use icp_events::{Event, Outcome, TaskId}; + + fn pkg_cache() -> (camino_tempfile::Utf8TempDir, PackageCache) { + let dir = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + let cache = PackageCache::new(dir.path().to_owned()).expect("package cache"); + (dir, cache) + } + + /// A [`ScriptRunner`] that reports lines of its own instead of running anything, + /// so the operation can be driven without spawning a shell. + struct ScriptedRunner { + lines: Vec, + fail: bool, + } + + #[async_trait] + impl ScriptRunner for ScriptedRunner { + async fn run_script( + &self, + _invocation: icp::canister::sync::script::ScriptInvocation, + stdio: Option, + ) -> Result, icp::canister::sync::script::ScriptRunError> { + if let Some(out) = &stdio { + for line in &self.lines { + out.line(line.clone()); + } + } + + if self.fail { + return Err(icp::canister::sync::script::ScriptRunError { + source: "boom".into(), + }); + } + + Ok(vec!["retained stderr".to_owned()]) + } + } + + fn canister_with_a_script_step(name: &str) -> Canister { + let mut canister = bare_canister(name); + canister.sync.steps = vec![SyncStep::Script(script::Adapter { + command: script::CommandField::Command("./deploy.sh".to_owned()), + })]; + canister + } + + async fn sync_one( + runner: ScriptedRunner, + name: &str, + ) -> (Vec, Result<(), SyncOperationError>) { + let (reporter, sink) = recording_reporter(); + let (_dir, cache) = pkg_cache(); + let cid = Principal::from_slice(&[7; 4]); + + let result = sync_many( + Arc::new(Syncer::new(Arc::new(runner))), + unreachable_agent(), + vec![(cid, "/work".into(), canister_with_a_script_step(name))], + "local".to_owned(), + "local".to_owned(), + BTreeMap::new(), + None, + &reporter, + false, + &cache, + ) + .await; + + (sink.events(), result) + } + + /// The whole shape of a sync, reported: the task, its step, the output the step + /// produced, and how it ended. + #[tokio::test] + async fn a_sync_reports_its_steps_and_their_output() { + let (events, result) = sync_one( + ScriptedRunner { + lines: vec!["uploading assets".to_owned()], + fail: false, + }, + "frontend", + ) + .await; + result.expect("sync should succeed"); + + assert_eq!( + events.first().unwrap(), + &Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Sync".to_owned() + }, + label: Some("frontend".to_owned()), + } + ); + assert!( + events.iter().any(|event| matches!( + event, + Event::StepStarted { id, index: 0, title } + if *id == TaskId(0) && title.contains("Syncing:") && title.ends_with("1 of 1") + )), + "{events:?}" + ); + assert!(events.contains(&Event::StepOutput { + id: TaskId(0), + line: "uploading assets".to_owned(), + })); + assert_eq!( + events.last().unwrap(), + &Event::TaskFinished { + id: TaskId(0), + outcome: Outcome::Success, + message: Some(format!( + "Synced successfully: {}", + Principal::from_slice(&[7; 4]) + )), + } + ); + } + + #[tokio::test] + async fn a_failed_sync_reports_the_failure_and_keeps_its_output() { + let (events, result) = sync_one( + ScriptedRunner { + lines: vec!["about to fall over".to_owned()], + fail: true, + }, + "frontend", + ) + .await; + let err = result.expect_err("sync should fail"); + assert!(err.to_string().contains("frontend")); + + assert!(events.contains(&Event::StepOutput { + id: TaskId(0), + line: "about to fall over".to_owned(), + })); + let Event::TaskFinished { + outcome, message, .. + } = events.last().unwrap().clone() + else { + panic!("a sync always finishes its task: {events:?}"); + }; + assert_eq!(outcome, Outcome::Failure); + assert!( + message + .as_deref() + .is_some_and(|m| m.starts_with("Failed to sync canister:")), + "{message:?}" + ); + } + + /// Tasks appear in the order the canisters were given, whichever order their + /// syncs happen to finish in. + #[tokio::test] + async fn tasks_are_started_in_the_order_the_canisters_were_given() { + use crate::operations::test_support::task_labels; + + let (reporter, sink) = recording_reporter(); + let (_dir, cache) = pkg_cache(); + let cid = Principal::from_slice(&[7; 4]); + + sync_many( + Arc::new(Syncer::new(Arc::new(ScriptedRunner { + lines: Vec::new(), + fail: false, + }))), + unreachable_agent(), + vec![ + (cid, "/work".into(), canister_with_a_script_step("frontend")), + (cid, "/work".into(), canister_with_a_script_step("backend")), + ], + "local".to_owned(), + "local".to_owned(), + BTreeMap::new(), + None, + &reporter, + false, + &cache, + ) + .await + .expect("sync should succeed"); + + assert_eq!( + task_labels(&sink.events()), + vec![Some("frontend".to_owned()), Some("backend".to_owned())] + ); + } +} diff --git a/crates/icp-cli/src/progress.rs b/crates/icp-cli/src/progress.rs deleted file mode 100644 index befdb894b..000000000 --- a/crates/icp-cli/src/progress.rs +++ /dev/null @@ -1,364 +0,0 @@ -use std::{collections::VecDeque, time::Duration}; - -use futures::Future; -use indicatif::{MultiProgress, ProgressBar as SimpleProgressBar, ProgressStyle}; -use itertools::Itertools; -use tokio::{sync::mpsc, task::JoinHandle}; -use tracing::debug; - -/// The maximum number of lines to display for a step output -pub(crate) const MAX_LINES_PER_STEP: usize = 10_000; - -// Animation frames for the spinner - creates a rotating star effect -const TICKS: &[&str] = &["✶", "✸", "✹", "✺", "✹", "✷"]; - -// Final tick symbols for different completion states -const TICK_EMPTY: &str = " "; -const TICK_SUCCESS: &str = "✔"; -const TICK_FAILURE: &str = "✘"; - -// Color schemes for different progress states -const COLOR_REGULAR: &str = "blue"; -const COLOR_SUCCESS: &str = "green"; -const COLOR_FAILURE: &str = "red"; - -/// The style a spinner carries while it is still running. -pub(crate) fn running_style() -> ProgressStyle { - make_style(TICK_EMPTY, COLOR_REGULAR) -} - -/// The style a spinner carries once it has succeeded. -pub(crate) fn success_style() -> ProgressStyle { - make_style(TICK_SUCCESS, COLOR_SUCCESS) -} - -/// The style a spinner carries once it has failed. -pub(crate) fn failure_style() -> ProgressStyle { - make_style(TICK_FAILURE, COLOR_FAILURE) -} - -/// How often a running spinner redraws itself. -pub(crate) const STEADY_TICK: Duration = Duration::from_millis(120); - -/// The style a byte-transfer bar carries. -pub(crate) fn byte_style() -> ProgressStyle { - ProgressStyle::default_bar() - .template("{prefix} [{elapsed_precise}] [{wide_bar:.cyan/blue}] {bytes}/{total_bytes} ({bytes_per_sec}, {eta})") - .expect("invalid progress bar template") - .progress_chars("#>-") -} - -// Creates a progress bar style with a spinner that transitions to a final tick symbol -// - end_tick: the symbol to display when the progress completes (success, failure, etc.) -// - color: the color theme for the spinner and text -fn make_style(end_tick: &str, color: &str) -> ProgressStyle { - // Template format: "[prefix] [spinner] [message]" - let tmpl = format!("{{prefix}} {{spinner:.{color}}} {{msg}}"); - - ProgressStyle::with_template(&tmpl) - .expect("invalid style template") - // Combine animation frames with the final completion symbol - .tick_strings(&[TICKS, &[end_tick]].concat()) -} - -/// A fixed-capacity rolling buffer that always holds the last `capacity` items. -#[derive(Debug)] -pub(crate) struct RollingLines { - buf: VecDeque, - capacity: usize, -} - -impl RollingLines { - /// Create a new buffer with a fixed capacity. - pub(crate) fn new(capacity: usize) -> Self { - let buf = VecDeque::with_capacity(capacity); - Self { buf, capacity } - } - - /// Push a new line, evicting the oldest if full. - pub(crate) fn push(&mut self, line: String) { - if self.buf.len() == self.capacity { - self.buf.pop_front(); - } - - self.buf.push_back(line); - } - - /// Get an iterator over the current contents (in order). - pub(crate) fn iter(&self) -> impl Iterator { - self.buf.iter().map(|s| s.as_str()) - } - - /// Convert the buffer into an iterator (in order). - pub(crate) fn into_iter(self) -> impl Iterator { - self.buf.into_iter() - } -} - -/// Settings for the progress manager -pub(crate) struct ProgressManagerSettings { - /// Whether to hide the progress bars - pub(crate) hidden: bool, -} - -/// Shared progress bar utilities for build and sync commands -pub(crate) struct ProgressManager { - pub(crate) multi_progress: MultiProgress, -} - -impl ProgressManager { - pub(crate) fn new(settings: ProgressManagerSettings) -> Self { - let multi_progress = MultiProgress::new(); - - if settings.hidden { - multi_progress.set_draw_target(indicatif::ProgressDrawTarget::hidden()); - } - - Self { multi_progress } - } - - /// Create a new progress bar with standard configuration - pub(crate) fn create_progress_bar(&self, canister_name: &str) -> SimpleProgressBar { - self.start_spinner( - SimpleProgressBar::new_spinner() - .with_style(running_style()) - .with_prefix(format!("[{canister_name}]")), - ) - } - - pub(crate) fn create_independent_progress_bar(&self) -> SimpleProgressBar { - self.start_spinner(SimpleProgressBar::new_spinner().with_style(running_style())) - } - - /// Show `pb` and start animating it. - /// - /// The bar must arrive fully configured: the ticker thread `enable_steady_tick` - /// spawns draws a frame immediately, so a prefix set afterwards races that first - /// tick and can lose, leaving a stray unprefixed frame on screen. - fn start_spinner(&self, pb: SimpleProgressBar) -> SimpleProgressBar { - let pb = self.multi_progress.add(pb); - - // Auto-tick spinner - pb.enable_steady_tick(STEADY_TICK); - - pb - } - - /// Create a new progress bar for a multi-step operation. - pub(crate) fn create_multi_step_progress_bar( - &self, - canister_name: &str, - output_label: &str, - ) -> MultiStepProgressBar { - MultiStepProgressBar { - progress_bar: self.create_progress_bar(canister_name), - canister_name: canister_name.to_string(), - output_label: output_label.to_string(), - finished_steps: Vec::new(), - in_progress: None, - } - } - - /// Execute a task with progress tracking and automatic style updates - pub(crate) async fn execute_with_progress( - progress_bar: &P, - task: F, - success_message: impl Fn() -> String, - error_message: impl Fn(&E) -> String, - ) -> Result - where - F: Future>, - P: ProgressBar, - { - // Delegate to execute_with_custom_progress with no special error handling - Self::execute_with_custom_progress( - progress_bar, - task, - success_message, - error_message, - |_| false, // No errors are treated as success - ) - .await - } - - /// Execute a task with custom progress handling for errors that should display as success - pub(crate) async fn execute_with_custom_progress( - progress_bar: &P, - task: F, - success_message: impl Fn() -> String, - error_message: impl Fn(&E) -> String, - is_success_error: impl Fn(&E) -> bool, - ) -> Result - where - F: Future>, - P: ProgressBar, - { - // Execute the task and capture the result - let result = task.await; - - // Update the progress bar style and message based on result - let (style, message) = match &result { - Ok(_) => (success_style(), success_message()), - Err(err) if is_success_error(err) => (success_style(), error_message(err)), - Err(err) => (failure_style(), error_message(err)), - }; - - progress_bar.set_style(style); - progress_bar.set_message(message); - progress_bar.finish(); - - result - } -} - -struct StepOutput { - title: String, - output: Vec, -} - -struct StepInProgress { - title: String, - receiver: JoinHandle>, -} - -pub(crate) struct MultiStepProgressBar { - progress_bar: SimpleProgressBar, - canister_name: String, - output_label: String, - finished_steps: Vec, - in_progress: Option, -} - -impl MultiStepProgressBar { - pub(crate) fn begin_step(&mut self, title: String) -> mpsc::Sender { - if self.in_progress.is_some() { - panic!("step already in progress"); - } - - let (tx, mut rx) = mpsc::channel::(100); - - let set_message = { - let pb = self.progress_bar.clone(); - let title = title.clone(); - - move |msg: String| { - pb.set_message(format!("{title}\n{msg}\n")); - } - }; - - // Handle logging from script commands - let handle = tokio::spawn(async move { - // Small rolling buffer to display current output while build is ongoing - let mut rolling = RollingLines::new(4); - // Total output buffer to display full build output later - let mut complete = RollingLines::new(MAX_LINES_PER_STEP); // We need _some_ limit to prevent consuming infinite memory - - while let Some(line) = rx.recv().await { - debug!("{line}"); - - // Update output buffer - rolling.push(line.clone()); - complete.push(line); - - // Update progress-bar with rolling terminal output - // Make the output - // │ look prettier... - // └ - let msg = rolling.iter().map(|s| format!("│ {s}")).join("\n"); - set_message(format!("{msg}\n└\n")); - } - - complete.into_iter().collect() - }); - - self.in_progress = Some(StepInProgress { - title, - receiver: handle, - }); - - tx - } - - pub(crate) async fn end_step(&mut self) { - let StepInProgress { title, receiver } = - self.in_progress.take().expect("no step in progress"); - let output = receiver.await.unwrap(); - - self.finished_steps.push(StepOutput { title, output }); - } - - /// Dump captured build output. When `all_steps` is true, output from every - /// step is included; otherwise only the last (failing) step is shown. - pub(crate) fn dump_output(&self, all_steps: bool) -> Vec { - let mut lines = Vec::new(); - - lines.push(format!( - "[{}] {} output:", - self.canister_name, self.output_label - )); - - let steps: &[StepOutput] = if all_steps { - &self.finished_steps - } else { - self.finished_steps - .last() - .map(std::slice::from_ref) - .unwrap_or_default() - }; - - for step_output in steps { - for line in step_output.title.lines() { - if !line.is_empty() { - lines.push(format!("[{}] {}:", self.canister_name, line)); - } - } - - if step_output.output.is_empty() { - lines.push(format!("[{}] ", self.canister_name)); - } else { - lines.extend( - step_output - .output - .iter() - .map(|s| format!("[{}] > {s}", self.canister_name)), - ); - } - } - - lines - } -} - -pub(crate) trait ProgressBar { - fn set_style(&self, style: ProgressStyle); - fn set_message(&self, message: String); - fn finish(&self); -} - -impl ProgressBar for MultiStepProgressBar { - fn set_style(&self, style: ProgressStyle) { - self.progress_bar.set_style(style); - } - - fn set_message(&self, message: String) { - self.progress_bar.set_message(message); - } - - fn finish(&self) { - self.progress_bar.finish(); - } -} - -impl ProgressBar for SimpleProgressBar { - fn set_style(&self, style: ProgressStyle) { - SimpleProgressBar::set_style(self, style); - } - - fn set_message(&self, message: String) { - SimpleProgressBar::set_message(self, message); - } - - fn finish(&self) { - SimpleProgressBar::finish(self); - } -} diff --git a/crates/icp-events/src/lib.rs b/crates/icp-events/src/lib.rs index 6e8f518fb..3fb6fe021 100644 --- a/crates/icp-events/src/lib.rs +++ b/crates/icp-events/src/lib.rs @@ -48,10 +48,12 @@ mod cancel; mod event; +mod output; mod reporter; mod sink; pub use cancel::{CancelToken, Cancelled}; pub use event::{Event, NoticeLevel, Outcome, TaskId, TaskKind}; +pub use output::{MAX_RECORDED_LINES_PER_STEP, OutputWriter, RecordedStep}; pub use reporter::{Reporter, Task}; pub use sink::{DiscardSink, EventSink, RecordingSink}; diff --git a/crates/icp-events/src/output.rs b/crates/icp-events/src/output.rs new file mode 100644 index 000000000..773f64802 --- /dev/null +++ b/crates/icp-events/src/output.rs @@ -0,0 +1,178 @@ +use std::{ + collections::VecDeque, + sync::{Arc, Mutex}, +}; + +use crate::{ + event::{Event, TaskId}, + reporter::Reporter, +}; + +/// How many of a step's output lines are kept for replay. +/// +/// Some limit is needed: a runaway command can print without end. Once a step is +/// over this, its oldest lines are dropped and the most recent ones survive, which +/// is the half worth showing after a failure. +pub const MAX_RECORDED_LINES_PER_STEP: usize = 10_000; + +/// One step's title and the output it produced. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct RecordedStep { + /// The title the step was started with. + pub title: String, + + /// Every line the step reported, oldest first, capped at + /// [`MAX_RECORDED_LINES_PER_STEP`]. + pub lines: Vec, +} + +/// A step being recorded. Holds its lines in a ring so the cap costs nothing. +#[derive(Debug)] +struct Recording { + title: String, + lines: VecDeque, +} + +/// The output of every step of one task, in the order the steps ran. +/// +/// Progress is transient — a bar redraws over it — but an operation that fails +/// wants the whole of the failing step back so it can print it once the bars are +/// gone. Keeping that here means each operation does not have to tee the lines it +/// hands out. +#[derive(Debug, Default)] +pub(crate) struct StepLog { + steps: Mutex>, +} + +impl StepLog { + /// Open a new step to record against. + pub(crate) fn begin(&self, title: String) { + self.steps + .lock() + .expect("step log poisoned") + .push(Recording { + title, + lines: VecDeque::new(), + }); + } + + /// Record a line against the step most recently opened. + /// + /// Lines that arrive with no step open are dropped: they have nowhere to be + /// replayed from. This is possible but unusual — a command whose output + /// outlives the step that ran it. + pub(crate) fn record(&self, line: &str) { + let mut steps = self.steps.lock().expect("step log poisoned"); + + if let Some(step) = steps.last_mut() { + if step.lines.len() == MAX_RECORDED_LINES_PER_STEP { + step.lines.pop_front(); + } + step.lines.push_back(line.to_owned()); + } + } + + /// Every step recorded so far. + pub(crate) fn recorded(&self) -> Vec { + self.steps + .lock() + .expect("step log poisoned") + .iter() + .map(|step| RecordedStep { + title: step.title.clone(), + lines: step.lines.iter().cloned().collect(), + }) + .collect() + } +} + +/// Where a running command's output lines go. +/// +/// This is what crosses a crate boundary: a library that runs a subprocess or a +/// plugin takes an `OutputWriter` and reports each line it reads, learning nothing +/// about what renders them. Cloning is cheap, and every clone writes to the same +/// task, so a writer can be handed to as many concurrent readers as a command has +/// output streams. +#[derive(Debug, Clone)] +pub struct OutputWriter { + reporter: Reporter, + id: TaskId, + log: Arc, +} + +impl OutputWriter { + pub(crate) fn new(reporter: Reporter, id: TaskId, log: Arc) -> Self { + Self { reporter, id, log } + } + + /// Report one line of output. + /// + /// Never blocks and never fails: with nothing rendering, a line simply goes + /// nowhere. + pub fn line(&self, line: impl Into) { + let line = line.into(); + self.log.record(&line); + self.reporter.emit(Event::StepOutput { id: self.id, line }); + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn log() -> StepLog { + StepLog::default() + } + + #[test] + fn steps_are_recorded_in_order_with_their_lines() { + let log = log(); + + log.begin("first".to_owned()); + log.record("a"); + log.record("b"); + log.begin("second".to_owned()); + log.record("c"); + + assert_eq!( + log.recorded(), + vec![ + RecordedStep { + title: "first".to_owned(), + lines: vec!["a".to_owned(), "b".to_owned()], + }, + RecordedStep { + title: "second".to_owned(), + lines: vec!["c".to_owned()], + }, + ] + ); + } + + #[test] + fn a_step_keeps_its_most_recent_lines_once_capped() { + let log = log(); + log.begin("noisy".to_owned()); + + for i in 0..MAX_RECORDED_LINES_PER_STEP + 2 { + log.record(&format!("line {i}")); + } + + let recorded = log.recorded(); + let lines = &recorded[0].lines; + assert_eq!(lines.len(), MAX_RECORDED_LINES_PER_STEP); + assert_eq!(lines.first().unwrap(), "line 2"); + assert_eq!( + lines.last().unwrap(), + &format!("line {}", MAX_RECORDED_LINES_PER_STEP + 1) + ); + } + + #[test] + fn lines_with_no_step_open_are_dropped() { + let log = log(); + log.record("nowhere to go"); + + assert!(log.recorded().is_empty()); + } +} diff --git a/crates/icp-events/src/reporter.rs b/crates/icp-events/src/reporter.rs index ec98ae264..d1ef7542b 100644 --- a/crates/icp-events/src/reporter.rs +++ b/crates/icp-events/src/reporter.rs @@ -10,6 +10,7 @@ use std::{ use crate::{ cancel::CancelToken, event::{Event, NoticeLevel, Outcome, TaskId, TaskKind}, + output::{OutputWriter, RecordedStep, StepLog}, sink::{DiscardSink, EventSink}, }; @@ -107,6 +108,7 @@ impl Reporter { next_step: 0, open_step: None, finished: false, + log: Arc::new(StepLog::default()), } } } @@ -124,6 +126,7 @@ pub struct Task { next_step: usize, open_step: Option, finished: bool, + log: Arc, } impl Task { @@ -165,19 +168,36 @@ impl Task { self.next_step += 1; self.open_step = Some(index); + let title = title.into(); + self.log.begin(title.clone()); + self.reporter.emit(Event::StepStarted { id: self.id, index, - title: title.into(), + title, }); } /// Report a line of output from the step in progress. pub fn step_output(&self, line: impl Into) { - self.reporter.emit(Event::StepOutput { - id: self.id, - line: line.into(), - }); + self.output().line(line); + } + + /// A handle for reporting the output of the step in progress. + /// + /// This is what gets handed to whatever actually produces the output — a + /// subprocess reader, a plugin runtime — so it can report lines without + /// depending on this task, or on anything that renders it. + pub fn output(&self) -> OutputWriter { + OutputWriter::new(self.reporter.clone(), self.id, self.log.clone()) + } + + /// Every step of this task, with the output it produced. + /// + /// Progress is transient, so an operation that has to explain a failure after + /// the fact reads the step back from here. + pub fn recorded_steps(&self) -> Vec { + self.log.recorded() } /// End the step in progress. @@ -405,6 +425,95 @@ mod tests { ); } + /// The rolling view a sink draws is transient, so a task also keeps its steps' + /// output for an operation that has to print the failing step afterwards. + #[test] + fn a_task_keeps_the_output_of_every_step() { + let (reporter, _sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("step 1"); + task.step_output("compiling"); + task.end_step(); + task.begin_step("step 2"); + task.output().line("optimizing"); + task.end_step(); + + assert_eq!( + task.recorded_steps(), + vec![ + crate::RecordedStep { + title: "step 1".into(), + lines: vec!["compiling".into()], + }, + crate::RecordedStep { + title: "step 2".into(), + lines: vec!["optimizing".into()], + }, + ] + ); + } + + /// A command has as many output streams as it has streams to read, so the + /// writer is handed out by clone. + #[test] + fn every_clone_of_a_writer_reports_to_the_same_task() { + let (reporter, sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("step 1"); + + let stdout = task.output(); + let stderr = stdout.clone(); + stdout.line("out"); + stderr.line("err"); + + let lines: Vec = sink + .events() + .into_iter() + .filter_map(|event| match event { + Event::StepOutput { id, line } if id == task.id() => Some(line), + _ => None, + }) + .collect(); + assert_eq!(lines, vec!["out".to_owned(), "err".to_owned()]); + } + + /// The writer outlives the borrow of the task, since it is handed to code that + /// keeps reporting while the operation moves on. + #[test] + fn a_writer_can_be_sent_to_another_thread() { + let (reporter, sink) = recorder(); + + let mut task = reporter.task( + TaskKind::Steps { + output_label: "Build".into(), + }, + "backend", + ); + task.begin_step("step 1"); + + let writer = task.output(); + std::thread::spawn(move || writer.line("from a thread")) + .join() + .unwrap(); + + assert!(sink.events().contains(&Event::StepOutput { + id: task.id(), + line: "from a thread".into(), + })); + } + #[test] fn finishing_closes_a_step_left_open() { let (reporter, sink) = recorder(); diff --git a/crates/icp-sync-plugin/Cargo.toml b/crates/icp-sync-plugin/Cargo.toml index 216e9c761..15e3c8baf 100644 --- a/crates/icp-sync-plugin/Cargo.toml +++ b/crates/icp-sync-plugin/Cargo.toml @@ -15,6 +15,7 @@ console.workspace = true hex.workspace = true ic-agent.workspace = true icp-canister-interfaces.workspace = true +icp-events.workspace = true snafu.workspace = true tokio.workspace = true wasmtime.workspace = true diff --git a/crates/icp-sync-plugin/src/runtime.rs b/crates/icp-sync-plugin/src/runtime.rs index fb284fb7f..84758546c 100644 --- a/crates/icp-sync-plugin/src/runtime.rs +++ b/crates/icp-sync-plugin/src/runtime.rs @@ -24,9 +24,9 @@ use bytes::Bytes; use camino::Utf8PathBuf; use candid::{Encode, Principal}; use ic_agent::Agent; +use icp_events::OutputWriter; use snafu::prelude::*; use tokio::io::{self, AsyncWrite}; -use tokio::sync::mpsc::Sender; use wasmtime_wasi::cli::{IsTerminal, StdoutStream}; use wasmtime_wasi::p2::{OutputStream, Pollable, StreamError}; use wasmtime_wasi::{DirPerms, FilePerms}; @@ -213,7 +213,7 @@ pub fn run_plugin( identity_principal: Principal, environment: String, compute_limit_secs: u64, - stdio: Option>, + stdio: Option, ) -> Result, RunPluginError> { use wasmtime::component::{Component, Linker}; use wasmtime::{Config, Engine, Store}; @@ -376,8 +376,8 @@ pub fn run_plugin( // `LineCapture` implements both `StdoutStream` (so it can be installed on a // `WasiCtxBuilder`) and `OutputStream` / `AsyncWrite` (so the bytes written // by the guest flow through the same code path). Each write is split on -// newlines; complete lines have ANSI escapes stripped and are pushed to the -// rolling-view `Sender` via `try_send` (best-effort). For stderr, +// newlines; complete lines have ANSI escapes stripped and are reported to the +// rolling-view `OutputWriter`. For stderr, // the same lines are also appended to `persistent`, which is drained by // `run_plugin()` after `exec()` returns. Total accepted bytes are capped at // `MAX_PLUGIN_OUTPUT` per stream; further bytes are dropped and `finalize` @@ -397,14 +397,14 @@ struct CaptureState { struct LineCapture { state: Arc>, label: &'static str, - forward: Option>, + forward: Option, persistent: Option>>>, } impl LineCapture { fn new( label: &'static str, - forward: Option>, + forward: Option, persistent: Option>>>, ) -> Self { Self { @@ -441,8 +441,8 @@ impl LineCapture { } fn emit(&self, line: String) { - if let Some(tx) = &self.forward { - let _ = tx.try_send(line.clone()); + if let Some(out) = &self.forward { + out.line(line.clone()); } if let Some(p) = &self.persistent { p.lock().unwrap().push(line); @@ -527,6 +527,33 @@ mod tests { use candid::Principal; use ic_agent::Agent; + use icp_events::{Event, RecordingSink, Reporter, TaskKind}; + + /// An [`OutputWriter`] whose lines can be read back, standing in for the + /// rolling step view the CLI would otherwise be drawing. + fn recording_writer() -> (OutputWriter, Arc) { + let sink = Arc::new(RecordingSink::new()); + let mut task = Reporter::new(sink.clone()).unlabelled_task(TaskKind::Steps { + output_label: "Sync".to_owned(), + }); + task.begin_step("plugin"); + + // The task is dropped here: a writer keeps reporting for as long as anything + // holds it, and the task's own start/finish events are not what these tests + // are about. + (task.output(), sink) + } + + /// Every line reported through the writer, in order. + fn reported_lines(sink: &RecordingSink) -> Vec { + sink.events() + .into_iter() + .filter_map(|event| match event { + Event::StepOutput { line, .. } => Some(line), + _ => None, + }) + .collect() + } fn dummy_agent() -> Agent { Agent::builder() @@ -761,7 +788,7 @@ mod tests { let Some(wasm_path) = option_env!("TEST_PLUGIN_WASM") else { return; }; - let (tx, mut rx) = tokio::sync::mpsc::channel::(16); + let (writer, sink) = recording_writer(); let result = tokio::task::block_in_place(|| { run_plugin( wasm_path.into(), @@ -774,12 +801,15 @@ mod tests { anon(), "print".to_string(), DEFAULT_PLUGIN_COMPUTE_LIMIT_SECS, - Some(tx), + Some(writer), ) }); assert!(result.is_ok()); - let msg = rx.try_recv().expect("expected stdout message on channel"); - assert!(msg.contains("stdout from plugin"), "got: {msg}"); + let reported = reported_lines(&sink); + assert!( + reported.iter().any(|l| l.contains("stdout from plugin")), + "got: {reported:?}" + ); } #[tokio::test(flavor = "multi_thread")] @@ -787,7 +817,7 @@ mod tests { let Some(wasm_path) = option_env!("TEST_PLUGIN_WASM") else { return; }; - let (tx, mut rx) = tokio::sync::mpsc::channel::(16); + let (writer, sink) = recording_writer(); let result = tokio::task::block_in_place(|| { run_plugin( wasm_path.into(), @@ -800,13 +830,16 @@ mod tests { anon(), "hello".to_string(), DEFAULT_PLUGIN_COMPUTE_LIMIT_SECS, - Some(tx), + Some(writer), ) }); let lines = result.expect("plugin should succeed"); assert_eq!(lines, vec!["hello".to_string()]); - // The same line is forwarded to the rolling-view channel. - let live = rx.try_recv().expect("expected stderr line on channel"); - assert!(live.contains("hello"), "got: {live}"); + // The same line is reported for the rolling view. + let reported = reported_lines(&sink); + assert!( + reported.iter().any(|l| l.contains("hello")), + "got: {reported:?}" + ); } } diff --git a/crates/icp/Cargo.toml b/crates/icp/Cargo.toml index 40690d523..d0fcb3470 100644 --- a/crates/icp/Cargo.toml +++ b/crates/icp/Cargo.toml @@ -35,6 +35,7 @@ ic-ledger-types = { workspace = true } ic-management-canister-types = { workspace = true } ic-utils = { workspace = true } icp-canister-interfaces = { workspace = true } +icp-events = { workspace = true } icp-sync-plugin = { workspace = true } icrc-ledger-types = { workspace = true } indexmap = { workspace = true } diff --git a/crates/icp/src/canister/build/mod.rs b/crates/icp/src/canister/build/mod.rs index d630d9ee4..c21ac501e 100644 --- a/crates/icp/src/canister/build/mod.rs +++ b/crates/icp/src/canister/build/mod.rs @@ -1,7 +1,7 @@ use async_trait::async_trait; +use icp_events::OutputWriter; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use crate::manifest::canister::BuildStep; use crate::package::PackageCache; @@ -30,7 +30,7 @@ pub trait Build: Sync + Send { &self, step: &BuildStep, params: &Params, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result<(), BuildError>; } @@ -43,7 +43,7 @@ impl Build for Builder { &self, step: &BuildStep, params: &Params, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result<(), BuildError> { match step { @@ -67,7 +67,7 @@ impl Build for UnimplementedMockBuilder { &self, _step: &BuildStep, _params: &Params, - _stdio: Option>, + _stdio: Option, _pkg_cache: &PackageCache, ) -> Result<(), BuildError> { unimplemented!("UnimplementedMockBuilder::build") diff --git a/crates/icp/src/canister/build/prebuilt.rs b/crates/icp/src/canister/build/prebuilt.rs index 774a102f9..9418b998d 100644 --- a/crates/icp/src/canister/build/prebuilt.rs +++ b/crates/icp/src/canister/build/prebuilt.rs @@ -1,5 +1,5 @@ +use icp_events::OutputWriter; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use crate::{canister::wasm, fs, manifest::adapter::prebuilt::Adapter, package::PackageCache}; @@ -17,7 +17,7 @@ pub enum PrebuiltError { pub(super) async fn build( adapter: &Adapter, params: &Params, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result<(), PrebuiltError> { let src = wasm::resolve( @@ -29,10 +29,8 @@ pub(super) async fn build( ) .await?; - if let Some(tx) = &stdio { - let _ = tx - .send(format!("Writing WASM file: {}", params.output)) - .await; + if let Some(out) = &stdio { + out.line(format!("Writing WASM file: {}", params.output)); } fs::copy(&src, ¶ms.output).context(CopyFileSnafu)?; diff --git a/crates/icp/src/canister/build/script.rs b/crates/icp/src/canister/build/script.rs index 488b40077..33e09087c 100644 --- a/crates/icp/src/canister/build/script.rs +++ b/crates/icp/src/canister/build/script.rs @@ -1,4 +1,4 @@ -use tokio::sync::mpsc::Sender; +use icp_events::OutputWriter; use crate::manifest::adapter::script::Adapter; @@ -9,7 +9,7 @@ use super::super::script::{ScriptError, execute}; pub(super) async fn build( adapter: &Adapter, params: &Params, - stdio: Option>, + stdio: Option, ) -> Result<(), ScriptError> { execute( adapter, @@ -69,6 +69,57 @@ mod tests { assert_eq!(out, "test\n".to_string()); } + /// A build step streams its output through an [`OutputWriter`], so what the + /// subprocess printed can be observed as events without a terminal anywhere in + /// the picture. + #[tokio::test] + async fn command_output_is_reported_through_the_writer() { + use std::sync::Arc; + + use icp_events::{Event, RecordingSink, Reporter, TaskKind}; + + let sink = Arc::new(RecordingSink::new()); + let mut task = Reporter::new(sink.clone()).task( + TaskKind::Steps { + output_label: "Build".to_owned(), + }, + "backend", + ); + task.begin_step("step 1 of 1"); + + let adapter = Adapter { + command: CommandField::Command("echo streamed-line".to_owned()), + }; + + build( + &adapter, + &Params { + path: "/".into(), + output: "/".into(), + environment: LOCAL.to_owned(), + }, + Some(task.output()), + ) + .await + .expect("failed to build script step"); + + let lines: Vec = sink + .events() + .into_iter() + .filter_map(|event| match event { + Event::StepOutput { line, .. } => Some(line), + _ => None, + }) + .collect(); + assert_eq!(lines, vec!["streamed-line".to_owned()]); + + // The same lines are kept for replay if the step turns out to have failed. + assert_eq!( + task.recorded_steps()[0].lines, + vec!["streamed-line".to_owned()] + ); + } + #[tokio::test] async fn multiple_commands() { // Create temporary file diff --git a/crates/icp/src/canister/script.rs b/crates/icp/src/canister/script.rs index 6974a745d..211db3daa 100644 --- a/crates/icp/src/canister/script.rs +++ b/crates/icp/src/canister/script.rs @@ -1,11 +1,11 @@ use std::process::Stdio; +use icp_events::OutputWriter; use snafu::prelude::*; use tokio::{ io::{AsyncBufReadExt, BufReader}, join, process::Command, - sync::mpsc::Sender, }; use crate::manifest::adapter::script::Adapter; @@ -53,7 +53,7 @@ pub(super) async fn execute( adapter: &Adapter, cwd: &Path, envs: &[(&str, &str)], - stdio: Option>, + stdio: Option, ) -> Result<(), ScriptError> { // Normalize `command` field based on whether it's a single command or multiple. execute_commands(&adapter.command.as_vec(), cwd, envs, stdio).await @@ -71,7 +71,7 @@ pub(super) async fn execute_commands( cmds: &[String], cwd: &Path, envs: &[(&str, &str)], - stdio: Option>, + stdio: Option, ) -> Result<(), ScriptError> { // Iterate over configured commands for input_cmd in cmds { @@ -118,8 +118,8 @@ pub(super) async fn execute_commands( async move { while let Ok(Some(line)) = stdout.next_line().await { - if let Some(sender) = &stdio { - let _ = sender.send(line).await; + if let Some(out) = &stdio { + out.line(line); } } Ok::<(), ScriptError>(()) @@ -133,8 +133,8 @@ pub(super) async fn execute_commands( async move { while let Ok(Some(line)) = stderr.next_line().await { - if let Some(sender) = &stdio { - let _ = sender.send(line).await; + if let Some(out) = &stdio { + out.line(line); } } Ok::<(), ScriptError>(()) diff --git a/crates/icp/src/canister/sync/mod.rs b/crates/icp/src/canister/sync/mod.rs index 519a75b71..2fa6a1e3f 100644 --- a/crates/icp/src/canister/sync/mod.rs +++ b/crates/icp/src/canister/sync/mod.rs @@ -4,8 +4,8 @@ use std::sync::Arc; use async_trait::async_trait; use candid::Principal; use ic_agent::Agent; +use icp_events::OutputWriter; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use crate::manifest::canister::SyncStep; use crate::package::PackageCache; @@ -46,7 +46,7 @@ pub trait Synchronize: Sync + Send { step: &SyncStep, params: &Params, agent: &Agent, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result, SynchronizeError>; } @@ -77,7 +77,7 @@ impl Synchronize for Syncer { step: &SyncStep, params: &Params, agent: &Agent, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result, SynchronizeError> { match step { @@ -112,7 +112,7 @@ impl Synchronize for UnimplementedMockSyncer { _step: &SyncStep, _params: &Params, _agent: &Agent, - _stdio: Option>, + _stdio: Option, _pkg_cache: &PackageCache, ) -> Result, SynchronizeError> { unimplemented!("UnimplementedMockSyncer::sync") @@ -139,7 +139,7 @@ mod tests { async fn run_script( &self, invocation: ScriptInvocation, - _stdio: Option>, + _stdio: Option, ) -> Result, ScriptRunError> { self.seen.lock().unwrap().push(invocation); Ok(vec![]) diff --git a/crates/icp/src/canister/sync/plugin.rs b/crates/icp/src/canister/sync/plugin.rs index 97056d64d..af7aa4509 100644 --- a/crates/icp/src/canister/sync/plugin.rs +++ b/crates/icp/src/canister/sync/plugin.rs @@ -1,11 +1,11 @@ use camino::Utf8PathBuf; use candid::Principal; use ic_agent::Agent; +use icp_events::OutputWriter; use icp_sync_plugin::{ DEFAULT_PLUGIN_COMPUTE_LIMIT_SECS, PLUGIN_COMPUTE_LIMIT_ENV, RunPluginError, run_plugin, }; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use crate::{canister::wasm, manifest::adapter::plugin::Adapter, package::PackageCache}; @@ -62,7 +62,7 @@ pub(super) async fn sync( agent: &Agent, environment: &str, proxy: Option, - stdio: Option>, + stdio: Option, pkg_cache: &PackageCache, ) -> Result, PluginError> { // 0. Resolve the compute-time limit up front so a malformed diff --git a/crates/icp/src/canister/sync/script.rs b/crates/icp/src/canister/sync/script.rs index 7c9d741d7..85cca462a 100644 --- a/crates/icp/src/canister/sync/script.rs +++ b/crates/icp/src/canister/sync/script.rs @@ -13,8 +13,8 @@ //! sync path. use async_trait::async_trait; +use icp_events::OutputWriter; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use crate::manifest::adapter::script::Adapter; use crate::prelude::*; @@ -91,7 +91,7 @@ pub trait ScriptRunner: Sync + Send { async fn run_script( &self, invocation: ScriptInvocation, - stdio: Option>, + stdio: Option, ) -> Result, ScriptRunError>; } @@ -103,7 +103,7 @@ impl ScriptRunner for HostScripts { async fn run_script( &self, invocation: ScriptInvocation, - stdio: Option>, + stdio: Option, ) -> Result, ScriptRunError> { let env_refs: Vec<(&str, &str)> = invocation .env diff --git a/crates/icp/src/canister/wasm.rs b/crates/icp/src/canister/wasm.rs index 2cf2b219d..378016650 100644 --- a/crates/icp/src/canister/wasm.rs +++ b/crates/icp/src/canister/wasm.rs @@ -1,8 +1,8 @@ use camino::{Utf8Path, Utf8PathBuf}; +use icp_events::OutputWriter; use reqwest::{Client, Method, Request}; use sha2::{Digest, Sha256}; use snafu::prelude::*; -use tokio::sync::mpsc::Sender; use url::Url; use crate::{ @@ -50,21 +50,21 @@ pub async fn resolve( source: &SourceField, base_dir: &Utf8Path, sha256: Option<&str>, - stdio: Option<&Sender>, + stdio: Option<&OutputWriter>, pkg_cache: &PackageCache, ) -> Result { match source { SourceField::Local(s) => { let path = base_dir.join(&s.path); if let Some(expected) = sha256 { - if let Some(tx) = stdio { - let _ = tx.send(format!("Reading wasm: {}", s.path)).await; + if let Some(out) = stdio { + out.line(format!("Reading wasm: {}", s.path)); } let bytes = read(&path).context(ReadLocalSnafu { path: s.path.clone(), })?; - if let Some(tx) = stdio { - let _ = tx.send("Verifying checksum".to_string()).await; + if let Some(out) = stdio { + out.line("Verifying checksum"); } let actual = hex::encode(Sha256::digest(&bytes)); ensure!( @@ -94,16 +94,16 @@ pub async fn resolve( .await .context(LockCacheSnafu)?; if let Some(path) = cached { - if let Some(tx) = stdio { - let _ = tx.send("Using cached file".to_string()).await; + if let Some(out) = stdio { + out.line("Using cached file"); } return Ok(path); } } let url = Url::parse(&s.url).context(ParseUrlSnafu)?; - if let Some(tx) = stdio { - let _ = tx.send(format!("Fetching wasm: {url}")).await; + if let Some(out) = stdio { + out.line(format!("Fetching wasm: {url}")); } let resp = Client::new() .execute(Request::new(Method::GET, url)) @@ -118,8 +118,8 @@ pub async fn resolve( // Use provided sha256 as cache key (after verifying), or compute from bytes. let cache_sha = match sha256 { Some(expected) => { - if let Some(tx) = stdio { - let _ = tx.send("Verifying checksum".to_string()).await; + if let Some(out) = stdio { + out.line("Verifying checksum"); } let actual = hex::encode(Sha256::digest(&bytes)); ensure!( diff --git a/crates/icp/src/manifest/mod.rs b/crates/icp/src/manifest/mod.rs index 0a811e358..a93174222 100644 --- a/crates/icp/src/manifest/mod.rs +++ b/crates/icp/src/manifest/mod.rs @@ -20,6 +20,7 @@ pub(crate) mod serde_helpers; pub use { adapter::plugin, adapter::prebuilt, + adapter::script, canister::{ ArgsFormat, BuildStep, BuildSteps, CanisterManifest, Instructions, ManifestInitArgs, SyncStep, SyncSteps, From 105be95c287305f3c4cabab5ca5f40e3025fff62 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Mon, 17 Aug 2026 20:28:45 +0000 Subject: [PATCH 08/14] docs: describe the progress inversion as complete The prose still said the inversion was partway done, with `build.rs`, `sync.rs` and `snapshot_transfer.rs` rendering directly and `progress.rs` awaiting removal. All of that has now shipped, so describe the end state: operations report events, `indicatif` is confined to `events.rs` bar the two bespoke spinners in `commands/`, and `OutputWriter` is how a library hands back the lines a step produced. Also adds the operation-level byte-progress test for a resumed transfer, and drops two `too_many_arguments` allows this repo's threshold of 12 makes unnecessary. --- .claude/CLAUDE.md | 2 +- .claude/architecture.md | 47 ++++++------ crates/icp-cli/src/commands/network/start.rs | 27 ++++--- .../src/operations/snapshot_transfer.rs | 75 +++++++++++++++++++ crates/icp-cli/src/operations/sync.rs | 2 - crates/icp-cli/tests/build_tests.rs | 12 +-- crates/icp-cli/tests/sync_tests.rs | 16 ++-- crates/icp-events/src/lib.rs | 5 ++ 8 files changed, 132 insertions(+), 54 deletions(-) diff --git a/.claude/CLAUDE.md b/.claude/CLAUDE.md index 7bcdd8150..d196cee0c 100644 --- a/.claude/CLAUDE.md +++ b/.claude/CLAUDE.md @@ -23,7 +23,7 @@ cargo fmt && cargo clippy # Run after changes pass tests - **`crates/icp-cli`**: Main CLI binary (`icp`) with command implementations - **`crates/icp`**: Core library with project model, manifest loading, canister management, network configuration - **`crates/icp-canister-interfaces`**: Canister interface definitions for ICP system canisters -- **`crates/icp-events`**: Progress and user-facing notices as data (`Event`, `Reporter`, `Task`, `EventSink`), so operations can report without depending on the terminal. serde + futures only +- **`crates/icp-events`**: Progress and user-facing notices as data (`Event`, `Reporter`, `Task`, `OutputWriter`, `EventSink`), so operations can report without depending on the terminal. serde + futures only - **`crates/schema-gen`**: JSON schema generation for manifest validation ### Command Structure diff --git a/.claude/architecture.md b/.claude/architecture.md index 7d9a4ca26..870b63343 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -80,32 +80,29 @@ Store management is in `crates/icp/src/store_id.rs`. ## Progress & User-Facing Output Operations in `crates/icp-cli/src/operations/` report progress as data, not as terminal -calls — an inversion that is partway done, so `build.rs`, `sync.rs` and -`snapshot_transfer.rs` still render directly. `crates/icp-events` defines the vocabulary -(`Event`, `Reporter`, `Task`, `EventSink`, `CancelToken`) and depends only on serde and -futures — never on `icp`, an async runtime, or anything terminal-shaped. -`crates/icp-cli/src/events.rs` holds `IndicatifSink`, the only place that maps events onto -`indicatif` bars. - -- New or converted operations take a `&Reporter`, never a `debug: bool` and never - `crate::progress` directly. Callers build one per operation with +calls. `crates/icp-events` defines the vocabulary (`Event`, `Reporter`, `Task`, +`OutputWriter`, `EventSink`, `CancelToken`) and depends only on serde and futures — never on +`icp`, an async runtime, or anything terminal-shaped. `crates/icp-cli/src/events.rs` holds +`IndicatifSink`, the only place that maps events onto `indicatif` bars, and the styles they +are drawn in. + +- Operations take a `&Reporter`, never a `debug: bool`. Callers build one per operation with `events::indicatif_reporter(ctx.debug)`. -- `crates/icp-cli/src/progress.rs` is the pre-inversion renderer. Do not add users. Whether - it is removable is a question for the compiler — delete it and run - `cargo check -p icp-cli --all-targets`; no grep is the gate. To survey the call sites, - search for the symbols, not the module path, because a nested `use crate::{ …, - progress::{…} }` never spells `crate::progress` (which is exactly how `commands/deploy.rs` - hides from that search): +- Nothing outside `events.rs` imports `indicatif`, with two exceptions that never went + through the shared renderer and build their own one-off spinners: + `commands/canister/migrate_id.rs` and `commands/identity/link/web.rs`. Everything else + reports events. To check that this still holds: ```bash - grep -rlE 'ProgressManager|MultiStepProgressBar|RollingLines|_style\(|indicatif' crates/icp-cli/src + grep -rl indicatif crates/icp-cli/src crates/icp/src ``` - That covers commands as well as operations, and both kinds of user: those going through - `progress.rs` and those driving `indicatif` themselves. Styles shared by the two renderers - (spinner styles, `STEADY_TICK`, `byte_style`) live in `progress.rs` so they cannot drift - while both exist — `operations/snapshot_transfer.rs`, for one, takes `byte_style` from - there but still builds the bar with `indicatif` directly. +- A library that produces output lines — a subprocess, a sync plugin — is handed an + `OutputWriter` rather than a channel. Each line becomes an `Event::StepOutput` and is kept + in the task's step log, capped at `MAX_RECORDED_LINES_PER_STEP`, so an operation can replay + the failing step after the bars are down. `operations/step_replay.rs` formats that replay; + read the steps back with `Task::recorded_steps` *before* finishing the task, since + finishing consumes it. - The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums `#[non_exhaustive]`, `TaskKind` closed. - Events do not drive `--json`. `--json` means the command's final result; progress never @@ -114,10 +111,14 @@ futures — never on `icp`, an async runtime, or anything terminal-shaped. `UserLayer` that prints `Level::INFO` to stderr unprefixed. `Event::Notice` is the event model's equivalent; the `info!`/`warn!`/`error!` calls inside `operations/` have not been converted yet. +- A bar has to be fully styled and labelled before it is shown, and a spinner before + `enable_steady_tick`: that call spawns a thread which draws immediately, so anything set + afterwards races the first frame. Operations are unit-tested by running them against `RecordingSink` and asserting on the -resulting `Vec`; see `operations/test_support.rs`. `events.rs` additionally compares -`IndicatifSink`'s rendered frames against `ProgressManager`'s to catch output regressions. +resulting `Vec`; see `operations/test_support.rs`. `events.rs::rendering` +additionally pins the frames `IndicatifSink` draws against the literal output of the +renderer it replaced, captured before that renderer was deleted. ## Telemetry diff --git a/crates/icp-cli/src/commands/network/start.rs b/crates/icp-cli/src/commands/network/start.rs index fc8d3fe41..1eb45a671 100644 --- a/crates/icp-cli/src/commands/network/start.rs +++ b/crates/icp-cli/src/commands/network/start.rs @@ -193,25 +193,24 @@ pub(crate) async fn exec(ctx: &Context, args: &StartArgs) -> Result<(), anyhow:: } else { // The version is not fresh or not cached, download it debug!("Downloading icp-cli-network-launcher version `{version}`"); - let task = - indicatif_reporter(debug).unlabelled_task(TaskKind::Spinner); + let task = indicatif_reporter(debug).unlabelled_task(TaskKind::Spinner); task.message(format!("Downloading icp-cli-network-launcher {version}...")); let version_slot: Arc> = Arc::new(OnceLock::new()); let version_capture = version_slot.clone(); let path = task .run( - async { - let (ver, path) = - download_launcher_version(pkg, version, &client).await?; - let _ = version_capture.set(ver); - anyhow::Ok(path) - }, - move || { - let ver = version_slot.get().map(String::as_str).unwrap(); - format!("Downloaded icp-cli-network-launcher {ver}") - }, - |err| format!("Failed to download icp-cli-network-launcher: {err}"), - ) + async { + let (ver, path) = + download_launcher_version(pkg, version, &client).await?; + let _ = version_capture.set(ver); + anyhow::Ok(path) + }, + move || { + let ver = version_slot.get().map(String::as_str).unwrap(); + format!("Downloaded icp-cli-network-launcher {ver}") + }, + |err| format!("Failed to download icp-cli-network-launcher: {err}"), + ) .await?; Ok(Some(path)) } diff --git a/crates/icp-cli/src/operations/snapshot_transfer.rs b/crates/icp-cli/src/operations/snapshot_transfer.rs index 335cc28fd..b08c869fa 100644 --- a/crates/icp-cli/src/operations/snapshot_transfer.rs +++ b/crates/icp-cli/src/operations/snapshot_transfer.rs @@ -890,3 +890,78 @@ pub fn load_metadata( } Ok(icp::fs::json::load(&metadata_path)?) } + +#[cfg(test)] +mod tests { + use super::*; + use crate::operations::test_support::{recording_reporter, unreachable_agent}; + use icp_events::{Event, TaskId, TaskKind}; + + /// A transfer that resumes reports the offset it recovered before anything else, + /// so the bar opens where the last attempt stopped rather than at zero. + /// + /// Nothing is uploaded here: the recorded offset already covers the whole blob, + /// which is the boundary case that leaves the chunk loop with no work and needs no + /// network. The reported position is the interesting part either way. + #[tokio::test] + async fn a_resumed_upload_reports_the_offset_it_starts_from() { + let (reporter, sink) = recording_reporter(); + let dir = camino_tempfile::Utf8TempDir::new().expect("temp dir"); + + let snapshot = SnapshotPaths::new(dir.path().to_owned()).expect("snapshot dir"); + let blob = vec![7u8; 4096]; + let uploaded = snapshot + .with_write(async |paths| { + paths.ensure_dirs()?; + icp::fs::write(&paths.blob_path(BlobType::WasmModule), &blob)?; + + let mut progress = UploadProgress::new("aa".to_owned()); + progress.wasm_module_offset = blob.len() as u64; + + let task = reporter.task( + TaskKind::Bytes { + total: blob.len() as u64, + }, + "WASM module", + ); + let uploaded = upload_blob_from_file( + &unreachable_agent(), + None, + Principal::from_slice(&[7; 4]), + &[0xaa], + BlobType::WasmModule, + paths, + &mut progress, + &task, + ) + .await?; + task.succeed("done"); + + Ok::<_, SnapshotTransferError>(uploaded) + }) + .await + .expect("lock") + .expect("nothing left to upload"); + + assert_eq!(uploaded, blob.len() as u64); + assert_eq!( + sink.events(), + vec![ + Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Bytes { total: 4096 }, + label: Some("WASM module".to_owned()), + }, + Event::TaskPosition { + id: TaskId(0), + position: 4096, + }, + Event::TaskFinished { + id: TaskId(0), + outcome: icp_events::Outcome::Success, + message: Some("done".to_owned()), + }, + ] + ); + } +} diff --git a/crates/icp-cli/src/operations/sync.rs b/crates/icp-cli/src/operations/sync.rs index 64c637122..7e4ccb8ed 100644 --- a/crates/icp-cli/src/operations/sync.rs +++ b/crates/icp-cli/src/operations/sync.rs @@ -33,7 +33,6 @@ struct SyncFailure { } /// Synchronizes a single canister using its configured sync steps -#[allow(clippy::too_many_arguments)] async fn sync_canister( syncer: &Arc, agent: &Agent, @@ -85,7 +84,6 @@ async fn sync_canister( /// /// `all_step_output` replays every step of a failed sync rather than just the one /// that failed, which is what `--debug` asks for. -#[allow(clippy::too_many_arguments)] pub(crate) async fn sync_many( syncer: Arc, agent: Agent, diff --git a/crates/icp-cli/tests/build_tests.rs b/crates/icp-cli/tests/build_tests.rs index c2e89fbf0..20be1900d 100644 --- a/crates/icp-cli/tests/build_tests.rs +++ b/crates/icp-cli/tests/build_tests.rs @@ -502,9 +502,9 @@ fn build_multiple_canisters() { .assert() .success() .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::progress: building canister-a")) - .stderr(contains("DEBUG icp::progress: building canister-b")) - .stderr(contains("DEBUG icp::progress: building canister-c").not()); + .stderr(contains("DEBUG icp::events: building canister-a")) + .stderr(contains("DEBUG icp::events: building canister-b")) + .stderr(contains("DEBUG icp::events: building canister-c").not()); } #[test] @@ -559,7 +559,7 @@ fn build_all_canisters_in_environment() { .success() .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::progress: building canister-a")) - .stderr(contains("DEBUG icp::progress: building canister-b")) - .stderr(contains("DEBUG icp::progress: building canister-c").not()); // not in test-env + .stderr(contains("DEBUG icp::events: building canister-a")) + .stderr(contains("DEBUG icp::events: building canister-b")) + .stderr(contains("DEBUG icp::events: building canister-c").not()); // not in test-env } diff --git a/crates/icp-cli/tests/sync_tests.rs b/crates/icp-cli/tests/sync_tests.rs index 31f72ef48..889642289 100644 --- a/crates/icp-cli/tests/sync_tests.rs +++ b/crates/icp-cli/tests/sync_tests.rs @@ -205,7 +205,7 @@ async fn sync_aborts_when_canister_not_running() { // sync aborts early with an actionable message; the `echo "syncing"` step // never runs, so its runtime progress output must not appear. (The `--debug` // config dump echoes the step's command text, so we check for the runtime - // `DEBUG icp::progress: syncing` marker rather than the bare word "syncing".) + // `DEBUG icp::events: syncing` marker rather than the bare word "syncing".) ctx.icp() .current_dir(&project_dir) .env("NO_COLOR", "1") @@ -221,7 +221,7 @@ async fn sync_aborts_when_canister_not_running() { .stderr( contains("asset sync requires it to be Running") .and(contains("icp canister start")) - .and(contains("DEBUG icp::progress: syncing").not()), + .and(contains("DEBUG icp::events: syncing").not()), ); } @@ -387,9 +387,9 @@ async fn sync_multiple_canisters() { .success() .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::progress: syncing canister-a")) - .stderr(contains("DEBUG icp::progress: syncing canister-b")) - .stderr(contains("DEBUG icp::progress: syncing canister-c").not()); + .stderr(contains("DEBUG icp::events: syncing canister-a")) + .stderr(contains("DEBUG icp::events: syncing canister-b")) + .stderr(contains("DEBUG icp::events: syncing canister-c").not()); } #[tokio::test] @@ -861,7 +861,7 @@ async fn sync_all_canisters_in_environment() { .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::progress: syncing canister-a")) - .stderr(contains("DEBUG icp::progress: syncing canister-b")) - .stderr(contains("DEBUG icp::progress: syncing canister-c").not()); // not in test-env + .stderr(contains("DEBUG icp::events: syncing canister-a")) + .stderr(contains("DEBUG icp::events: syncing canister-b")) + .stderr(contains("DEBUG icp::events: syncing canister-c").not()); // not in test-env } diff --git a/crates/icp-events/src/lib.rs b/crates/icp-events/src/lib.rs index 3fb6fe021..b7cac3c66 100644 --- a/crates/icp-events/src/lib.rs +++ b/crates/icp-events/src/lib.rs @@ -13,6 +13,11 @@ //! `warn!` / `error!` calls that this CLI prints as product output rather than as //! logging. //! +//! Code that produces the output of a step — a subprocess reader, a plugin runtime — +//! is handed an [`OutputWriter`] rather than a channel. Each line it reports becomes +//! an [`Event::StepOutput`] and is also kept in the task's step log, so an operation +//! that fails can replay the whole failing step once the progress it drew is gone. +//! //! # Stability //! //! The event model is **not** semver-stable. It ships at `0.x`, moves in lockstep From e71f11aa92ebf921ee30d91d6e5b2f78983244f0 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 04:25:04 +0000 Subject: [PATCH 09/14] no-mistakes(review): strip ANSI from recorded frames; narrow doc grep; dedupe emit --- .claude/architecture.md | 2 +- crates/icp-cli/src/events.rs | 115 +++++++++++++++++++++++++++++------ 2 files changed, 96 insertions(+), 21 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index 870b63343..fe33928cd 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -94,7 +94,7 @@ are drawn in. reports events. To check that this still holds: ```bash - grep -rl indicatif crates/icp-cli/src crates/icp/src + grep -rl 'use indicatif' crates/icp-cli/src crates/icp/src ``` - A library that produces output lines — a subprocess, a sync plugin — is handed an diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 8d5c14c8b..357da5c01 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -239,6 +239,16 @@ impl IndicatifSink { } } + /// Run `f` against the bar belonging to `id`. + /// + /// A task with no bar is not an error: an event can arrive after its task has + /// finished and been removed, and the code being replaced ignored those too. + fn with_bar(&self, id: TaskId, f: impl FnOnce(&mut BarState)) { + if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { + f(state); + } + } + /// Redraw the step in progress: its title, then the tail of its output. fn redraw_step(state: &BarState) { let Some(title) = &state.step_title else { @@ -259,37 +269,29 @@ impl EventSink for IndicatifSink { Event::TaskStarted { id, kind, label } => self.start(id, kind, label), Event::TaskMessage { id, message } => { - if let Some(state) = self.bars.lock().expect("bars poisoned").get(&id) { - state.bar.set_message(message); - } + self.with_bar(id, |state| state.bar.set_message(message)); } Event::TaskPosition { id, position } => { - if let Some(state) = self.bars.lock().expect("bars poisoned").get(&id) { - state.bar.set_position(position); - } + self.with_bar(id, |state| state.bar.set_position(position)); } - Event::StepStarted { id, title, .. } => { - if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { - state.step_title = Some(title); - state.visible = RollingLines::new(VISIBLE_STEP_LINES); - } - } + Event::StepStarted { id, title, .. } => self.with_bar(id, |state| { + state.step_title = Some(title); + state.visible = RollingLines::new(VISIBLE_STEP_LINES); + }), Event::StepOutput { id, line } => { debug!("{line}"); - if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { + self.with_bar(id, |state| { state.visible.push(line); Self::redraw_step(state); - } + }); } Event::StepFinished { id, .. } => { - if let Some(state) = self.bars.lock().expect("bars poisoned").get_mut(&id) { - state.step_title = None; - } + self.with_bar(id, |state| state.step_title = None); } Event::TaskFinished { @@ -339,14 +341,48 @@ mod rendering { /// compared directly between two runs. const ANIMATION_GLYPHS: [char; 5] = ['✶', '✸', '✹', '✺', '✷']; + /// Drop the colour codes from a frame. + /// + /// `indicatif` only calls `ProgressStyle::set_for_stderr` when its draw target + /// *is* stderr, which a [`TermLike`] target never is, so the styled template + /// fields fall back to `console`'s stdout-based colour detection: run from a + /// terminal the frames arrive wrapped in SGR codes, run from a pipe they do not. + /// What is drawn does not depend on how the developer started `cargo test`, so + /// the codes come off before anything else looks at the frame. + fn strip_ansi(frame: &str) -> String { + let mut out = String::with_capacity(frame.len()); + let mut chars = frame.chars(); + + while let Some(c) = chars.next() { + if c != '\u{1b}' { + out.push(c); + continue; + } + + // A CSI sequence — `ESC [`, which is all `console` emits — runs up to and + // including its final byte in `@..=~`. Any other escape is two characters. + if chars.next() == Some('[') { + for c in chars.by_ref() { + if ('@'..='~').contains(&c) { + break; + } + } + } + } + + out + } + impl RecordingTerm { /// Every frame drawn, with the spinner's animation collapsed to a single /// marker and the resulting consecutive duplicates removed. /// /// What survives is the sequence of *states* a bar passed through — prefix, - /// message, and final tick — which is exactly what has to match. Three things + /// message, and final tick — which is exactly what has to match. Four things /// are dropped on the way: /// + /// - the colour codes, which depend on whether the test binary's stdout is a + /// terminal rather than on what was drawn (see [`strip_ansi`]); /// - the blank line indicatif writes to pad out the rest of the terminal row, /// which is a function of the frame it follows; /// - the animation glyph, which advances on a timer and so differs run to run; @@ -360,6 +396,7 @@ mod rendering { .lock() .expect("writes poisoned") .iter() + .map(|frame| strip_ansi(frame)) .filter(|frame| !frame.trim().is_empty()) .map(|frame| { frame @@ -379,14 +416,15 @@ mod rendering { frames } - /// Every frame drawn, untouched apart from dropping the blank padding lines. + /// Every frame drawn, untouched apart from dropping the blank padding lines + /// and the environment-dependent colour codes. pub(super) fn raw_frames(&self) -> Vec { self.writes .lock() .expect("writes poisoned") .iter() + .map(|frame| strip_ansi(frame)) .filter(|frame| !frame.trim().is_empty()) - .cloned() .collect() } @@ -455,6 +493,43 @@ mod rendering { )))) } + /// Whether the recorded frames carry colour codes is a property of the machine + /// the tests run on, not of the sink: a [`TermLike`] draw target is never stderr, + /// so `indicatif` leaves the styled fields following `console`'s stdout-based + /// detection, and the goldens below would only hold when `cargo test` was piped. + /// Both views have to normalize that away before the animation-glyph and + /// message-less-frame rules can see anything either. + #[test] + fn normalization_strips_the_colour_codes_a_terminal_would_add() { + let term = RecordingTerm::default(); + for line in [ + "[backend] \u{1b}[34m✶\u{1b}[0m ", + "[backend] \u{1b}[34m✶\u{1b}[0m Installing...", + "[backend] \u{1b}[32m✔\u{1b}[0m Installed successfully", + ] { + term.write_line(line).expect("recording cannot fail"); + } + + assert_eq!( + term.raw_frames(), + [ + "[backend] ✶ ", + "[backend] ✶ Installing...", + "[backend] ✔ Installed successfully", + ] + ); + + // The message-less frame still drops out, which the trailing-glyph rule can + // only tell once the reset code sitting after that glyph is gone. + assert_eq!( + term.frames(), + [ + "[backend] ~ Installing...", + "[backend] ✔ Installed successfully", + ] + ); + } + /// Every frame the event stream draws for one canister's outcome. fn frames_for( result: Result<(), E>, From c284f72e078eec216edde0dc9f40bc2c2ac2f418 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 04:54:12 +0000 Subject: [PATCH 10/14] no-mistakes(document): correct sync-plugin design doc for OutputWriter --- .claude/architecture.md | 4 +++- crates/icp-sync-plugin/DESIGN.md | 19 +++++++++++-------- crates/icp/src/canister/script.rs | 4 ++-- 3 files changed, 16 insertions(+), 11 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index fe33928cd..356d4def9 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -87,7 +87,9 @@ calls. `crates/icp-events` defines the vocabulary (`Event`, `Reporter`, `Task`, are drawn in. - Operations take a `&Reporter`, never a `debug: bool`. Callers build one per operation with - `events::indicatif_reporter(ctx.debug)`. + `events::indicatif_reporter(ctx.debug)`. The multi-canister operations + (`build_many`, `sync_many`, `create_bundle`) still take one bool, `all_step_output`: it + decides how much of a failure is replayed, not how anything is drawn. - Nothing outside `events.rs` imports `indicatif`, with two exceptions that never went through the shared renderer and build their own one-off spinners: `commands/canister/migrate_id.rs` and `commands/identity/link/web.rs`. Everything else diff --git a/crates/icp-sync-plugin/DESIGN.md b/crates/icp-sync-plugin/DESIGN.md index 099a14714..2669c8d2c 100644 --- a/crates/icp-sync-plugin/DESIGN.md +++ b/crates/icp-sync-plugin/DESIGN.md @@ -53,7 +53,8 @@ crates/icp-sync-plugin/ lib.rs — public API: run_plugin(), RunPluginError runtime.rs — wasmtime component setup, HostState, bindgen!, exec() call sync-plugin.wit — WIT interface (source of truth) - Cargo.toml — wasmtime, wasmtime-wasi, ic-agent, candid, camino, snafu, tokio + Cargo.toml — wasmtime, wasmtime-wasi, ic-agent, candid, camino, snafu, + tokio, icp-events ``` Public function: @@ -70,7 +71,7 @@ pub fn run_plugin( identity_principal: Principal, environment: String, compute_limit_secs: u64, - stdio: Option>, + stdio: Option, ) -> Result, RunPluginError> ``` @@ -81,7 +82,8 @@ preopens each `dir` from `base_dir.join(dir)` and reads each `file` from both inside the runtime means the path-safety logic (below) lives in one place and stays private to this crate — the CLI just forwards strings. The returned `Vec` is the plugin's persistent stderr lines (see stdio capture below); -`stdio`, when set, receives the rolling progress lines live. +`stdio`, when set, is the `icp_events::OutputWriter` that receives the rolling +progress lines live. ### Declared-path safety (no symlinks) @@ -147,11 +149,12 @@ to `DEFAULT_PLUGIN_COMPUTE_LIMIT_SECS` (60) when unset. ### stdio capture `LineCapture` implements `StdoutStream`/`OutputStream`, splits guest output on -newlines, strips ANSI codes, and (best-effort) forwards each complete line to -the `stdio` channel for the rolling step view. stderr lines are additionally -accumulated and returned from `run_plugin` so the CLI can reprint them -persistently. Each stream is capped at 1 MiB; overflow is dropped and a single -truncation note is emitted on `finalize`. +newlines, strips ANSI codes, and reports each complete line to the `stdio` +`OutputWriter` for the rolling step view — synchronously, so a noisy plugin no +longer loses lines by outrunning a bounded channel. stderr lines are +additionally accumulated and returned from `run_plugin` so the CLI can reprint +them persistently. Each stream is capped at 1 MiB; overflow is dropped and a +single truncation note is emitted on `finalize`. ### `crates/icp/src/manifest/adapter/plugin.rs` diff --git a/crates/icp/src/canister/script.rs b/crates/icp/src/canister/script.rs index 211db3daa..3a5f48621 100644 --- a/crates/icp/src/canister/script.rs +++ b/crates/icp/src/canister/script.rs @@ -113,7 +113,7 @@ pub(super) async fn execute_commands( // // Stdout tokio::spawn({ - // Clone the stdio sender for use in the stdout handling task + // Clone the stdio writer for use in the stdout handling task let stdio = stdio.clone(); async move { @@ -128,7 +128,7 @@ pub(super) async fn execute_commands( // // Stderr tokio::spawn({ - // Clone the stdio sender for use in the stderr handling task + // Clone the stdio writer for use in the stderr handling task let stdio = stdio.clone(); async move { From 314cbaad6e87ba9ed807b84fb71ef5f8ff0303db Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 12:11:07 +0000 Subject: [PATCH 11/14] fix(events): name the canister in step output logged under --debug Under `--debug` the progress bars are hidden, so the `debug!` line the sink logs for each step-output event was the only record of a build's output - and it carried just the line. Canisters build in parallel, so several of them interleaved into a stream with nothing saying which canister printed what. The bars themselves have always shown the name in their prefix, so this was an inconsistency between the two paths rather than a missing feature. `BarState` now keeps the prefix it gave the bar, and the log line reuses it, so `[backend] compiling` reads the same way the bar does. Byte tasks label their bars undecorated and keep doing so here; they report no step output today, so that only settles the shape. The prefix is kept at construction rather than read back off the bar, and a line whose task is unknown - or which has no label - is still logged, bare, rather than dropped for want of a prefix. Verified on a real parallel build: five canisters under `--debug` produced 20 output lines, every one attributed to the canister that emitted it, with the canister changing between every consecutive pair. --- .claude/architecture.md | 5 + crates/icp-cli/src/events.rs | 180 ++++++++++++++++++++++++++-- crates/icp-cli/tests/build_tests.rs | 12 +- crates/icp-cli/tests/sync_tests.rs | 19 +-- 4 files changed, 194 insertions(+), 22 deletions(-) diff --git a/.claude/architecture.md b/.claude/architecture.md index 356d4def9..ae45cdb0b 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -113,6 +113,11 @@ are drawn in. `UserLayer` that prints `Level::INFO` to stderr unprefixed. `Event::Notice` is the event model's equivalent; the `info!`/`warn!`/`error!` calls inside `operations/` have not been converted yet. +- Under `--debug` the bars are hidden, so the `debug!` line the sink logs for each + `Event::StepOutput` is the only thing tying that line to the canister that printed it — + and canisters build in parallel, interleaving their output. `BarState` therefore keeps the + prefix it gave the bar, and the log line reuses it, so both paths name a canister the same + way. Anything else that has to name a task should read that prefix rather than the bar. - A bar has to be fully styled and labelled before it is shown, and a spinner before `enable_steady_tick`: that call spawns a thread which draws immediately, so anything set afterwards races the first frame. diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 357da5c01..3d4e38500 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -132,6 +132,10 @@ impl std::fmt::Debug for IndicatifSink { /// Everything needed to keep drawing one task. struct BarState { bar: ProgressBar, + /// The prefix the bar is drawn with, kept here as well because the bars are + /// hidden under `--debug` and the step output logged there still has to say + /// which canister produced it. + prefix: Option, /// Byte bars carry their own template, so they do not take the spinner's /// success/failure styles when they finish. styled_spinner: bool, @@ -170,18 +174,26 @@ impl IndicatifSink { // after `enable_steady_tick` races that first tick and can lose — which is // what drew a stray unprefixed spinner frame. See // `tests::a_spinner_is_labelled_before_its_first_tick`. + // Byte bars label themselves undecorated; spinners wrap the name in + // brackets. Both match what the code being replaced did, and the same string + // is kept on the `BarState` so anything else that has to name the task reads + // the same as the bar. + let prefix = label.map(|label| match kind { + TaskKind::Bytes { .. } => label, + _ => format!("[{label}]"), + }); + let state = match kind { TaskKind::Bytes { total } => { - // Byte bars label themselves undecorated; spinners wrap the name in - // brackets. Both match what the code being replaced did. let bar = ProgressBar::new(total).with_style(byte_style()); - let bar = match label { - Some(label) => bar.with_prefix(label), + let bar = match &prefix { + Some(prefix) => bar.with_prefix(prefix.clone()), None => bar, }; BarState { bar: self.multi.add(bar), + prefix, styled_spinner: false, step_title: None, visible: RollingLines::new(VISIBLE_STEP_LINES), @@ -191,8 +203,8 @@ impl IndicatifSink { // differs, and steps build a richer one. _ => { let bar = ProgressBar::new_spinner().with_style(running_style()); - let bar = match label { - Some(label) => bar.with_prefix(format!("[{label}]")), + let bar = match &prefix { + Some(prefix) => bar.with_prefix(prefix.clone()), None => bar, }; @@ -201,6 +213,7 @@ impl IndicatifSink { BarState { bar, + prefix, styled_spinner: true, step_title: None, visible: RollingLines::new(VISIBLE_STEP_LINES), @@ -249,6 +262,15 @@ impl IndicatifSink { } } + /// The prefix the bar for `id` is drawn with, if it has one. + fn prefix_of(&self, id: TaskId) -> Option { + self.bars + .lock() + .expect("bars poisoned") + .get(&id) + .and_then(|state| state.prefix.clone()) + } + /// Redraw the step in progress: its title, then the tail of its output. fn redraw_step(state: &BarState) { let Some(title) = &state.step_title else { @@ -282,7 +304,14 @@ impl EventSink for IndicatifSink { }), Event::StepOutput { id, line } => { - debug!("{line}"); + // Under `--debug` the bars are hidden, so this log line is the only + // place a canister name can appear — and several canisters build at + // once, interleaving their output. Carry the bar's own prefix so the + // two paths read the same way. + match self.prefix_of(id) { + Some(prefix) => debug!("{prefix} {line}"), + None => debug!("{line}"), + } self.with_bar(id, |state| { state.visible.push(line); @@ -947,6 +976,143 @@ mod tests { ); } + /// Every `DEBUG` message emitted while `f` runs, in order. + /// + /// The step-output log line is the only record of a build's output under + /// `--debug`, where the bars are hidden, so what it says is worth asserting on + /// directly rather than through the bar it is standing in for. + fn captured_debug_lines(f: impl FnOnce()) -> Vec { + use std::sync::{Arc, Mutex}; + use tracing::{Event as TracingEvent, Level, Subscriber, field}; + use tracing_subscriber::{layer::Context, prelude::*, registry::LookupSpan}; + + #[derive(Clone, Default)] + struct Capture(Arc>>); + + impl LookupSpan<'a>> tracing_subscriber::Layer for Capture { + fn on_event(&self, event: &TracingEvent<'_>, _ctx: Context<'_, S>) { + if *event.metadata().level() != Level::DEBUG { + return; + } + + struct Message(String); + impl field::Visit for Message { + fn record_debug(&mut self, f: &field::Field, value: &dyn std::fmt::Debug) { + if f.name() == "message" { + self.0 = format!("{value:?}"); + } + } + } + + let mut message = Message(String::new()); + event.record(&mut message); + self.0.lock().expect("capture poisoned").push(message.0); + } + } + + let capture = Capture::default(); + let lines = capture.0.clone(); + // No target filter: the layer takes every `DEBUG` event and the assertions + // below name the exact lines, so a filter would only be another thing able + // to make the test pass by seeing nothing. + tracing::subscriber::with_default(tracing_subscriber::registry().with(capture), f); + + lines.lock().expect("capture poisoned").clone() + } + + /// A step's output is logged with the canister name, because under `--debug` the + /// bars that would carry it are hidden and several canisters build at once. + #[test] + fn step_output_is_logged_with_the_canister_that_produced_it() { + let sink = sink(); + + let lines = captured_debug_lines(|| { + for (id, name) in [(0, "backend"), (1, "frontend")] { + sink.emit(Event::TaskStarted { + id: TaskId(id), + kind: TaskKind::Steps { + output_label: "Build".into(), + }, + label: Some(name.into()), + }); + } + + // Interleaved, the way two canisters building at once arrive. + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "compiling backend".into(), + }); + sink.emit(Event::StepOutput { + id: TaskId(1), + line: "bundling frontend".into(), + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "linking backend".into(), + }); + }); + + assert_eq!( + lines, + [ + "[backend] compiling backend", + "[frontend] bundling frontend", + "[backend] linking backend", + ] + ); + } + + /// An unlabelled task has no name to attribute its output to, and a line still + /// has to reach the log rather than being dropped for want of a prefix. + #[test] + fn an_unlabelled_task_logs_its_output_unattributed() { + let sink = sink(); + + let lines = captured_debug_lines(|| { + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Steps { + output_label: "Build".into(), + }, + label: None, + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "no one to blame".into(), + }); + + // A line arriving after its task finished is logged too, bare. + sink.emit(Event::StepOutput { + id: TaskId(9), + line: "late line".into(), + }); + }); + + assert_eq!(lines, ["no one to blame", "late line"]); + } + + /// A byte task's label is undecorated on its bar, so it stays undecorated here + /// too. Byte transfers report no step output today, so this only fixes what the + /// shape would be rather than changing anything visible. + #[test] + fn a_byte_task_attributes_output_with_its_undecorated_label() { + let sink = sink(); + + let lines = captured_debug_lines(|| { + sink.emit(Event::TaskStarted { + id: TaskId(0), + kind: TaskKind::Bytes { total: 100 }, + label: Some("WASM module".into()), + }); + sink.emit(Event::StepOutput { + id: TaskId(0), + line: "chunk 1".into(), + }); + }); + + assert_eq!(lines, ["WASM module chunk 1"]); + } + #[test] fn events_for_an_unknown_task_are_ignored() { let sink = sink(); diff --git a/crates/icp-cli/tests/build_tests.rs b/crates/icp-cli/tests/build_tests.rs index 20be1900d..3c54232fd 100644 --- a/crates/icp-cli/tests/build_tests.rs +++ b/crates/icp-cli/tests/build_tests.rs @@ -502,9 +502,9 @@ fn build_multiple_canisters() { .assert() .success() .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::events: building canister-a")) - .stderr(contains("DEBUG icp::events: building canister-b")) - .stderr(contains("DEBUG icp::events: building canister-c").not()); + .stderr(contains("DEBUG icp::events: [canister-a] building canister-a")) + .stderr(contains("DEBUG icp::events: [canister-b] building canister-b")) + .stderr(contains("DEBUG icp::events: [canister-c] building canister-c").not()); } #[test] @@ -559,7 +559,7 @@ fn build_all_canisters_in_environment() { .success() .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::events: building canister-a")) - .stderr(contains("DEBUG icp::events: building canister-b")) - .stderr(contains("DEBUG icp::events: building canister-c").not()); // not in test-env + .stderr(contains("DEBUG icp::events: [canister-a] building canister-a")) + .stderr(contains("DEBUG icp::events: [canister-b] building canister-b")) + .stderr(contains("DEBUG icp::events: [canister-c] building canister-c").not()); // not in test-env } diff --git a/crates/icp-cli/tests/sync_tests.rs b/crates/icp-cli/tests/sync_tests.rs index 889642289..75c8d165a 100644 --- a/crates/icp-cli/tests/sync_tests.rs +++ b/crates/icp-cli/tests/sync_tests.rs @@ -204,8 +204,9 @@ async fn sync_aborts_when_canister_not_running() { // sync aborts early with an actionable message; the `echo "syncing"` step // never runs, so its runtime progress output must not appear. (The `--debug` - // config dump echoes the step's command text, so we check for the runtime - // `DEBUG icp::events: syncing` marker rather than the bare word "syncing".) + // config dump echoes the step's command text, so we look for the shape only the + // runtime log has: step output is logged as `[] `, so a line + // reading `] syncing` can only have come from the step actually running.) ctx.icp() .current_dir(&project_dir) .env("NO_COLOR", "1") @@ -221,7 +222,7 @@ async fn sync_aborts_when_canister_not_running() { .stderr( contains("asset sync requires it to be Running") .and(contains("icp canister start")) - .and(contains("DEBUG icp::events: syncing").not()), + .and(contains("] syncing").not()), ); } @@ -387,9 +388,9 @@ async fn sync_multiple_canisters() { .success() .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::events: syncing canister-a")) - .stderr(contains("DEBUG icp::events: syncing canister-b")) - .stderr(contains("DEBUG icp::events: syncing canister-c").not()); + .stderr(contains("DEBUG icp::events: [canister-a] syncing canister-a")) + .stderr(contains("DEBUG icp::events: [canister-b] syncing canister-b")) + .stderr(contains("DEBUG icp::events: [canister-c] syncing canister-c").not()); } #[tokio::test] @@ -861,7 +862,7 @@ async fn sync_all_canisters_in_environment() { .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::events: syncing canister-a")) - .stderr(contains("DEBUG icp::events: syncing canister-b")) - .stderr(contains("DEBUG icp::events: syncing canister-c").not()); // not in test-env + .stderr(contains("DEBUG icp::events: [canister-a] syncing canister-a")) + .stderr(contains("DEBUG icp::events: [canister-b] syncing canister-b")) + .stderr(contains("DEBUG icp::events: [canister-c] syncing canister-c").not()); // not in test-env } From 24e0faeafad695f895b1e4be30688f8cc90c7029 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 12:45:05 +0000 Subject: [PATCH 12/14] no-mistakes(test): fix flaky debug-capture test helper via global subscriber --- crates/icp-cli/src/events.rs | 61 +++++++++++++++++++++++++++++------- 1 file changed, 50 insertions(+), 11 deletions(-) diff --git a/crates/icp-cli/src/events.rs b/crates/icp-cli/src/events.rs index 3d4e38500..e3e83a4b4 100644 --- a/crates/icp-cli/src/events.rs +++ b/crates/icp-cli/src/events.rs @@ -982,12 +982,24 @@ mod tests { /// `--debug`, where the bars are hidden, so what it says is worth asserting on /// directly rather than through the bar it is standing in for. fn captured_debug_lines(f: impl FnOnce()) -> Vec { - use std::sync::{Arc, Mutex}; + use std::collections::HashMap; + use std::sync::{Mutex, OnceLock}; + use std::thread::{self, ThreadId}; use tracing::{Event as TracingEvent, Level, Subscriber, field}; use tracing_subscriber::{layer::Context, prelude::*, registry::LookupSpan}; - #[derive(Clone, Default)] - struct Capture(Arc>>); + /// The lines captured for each thread currently inside this helper. + /// + /// A thread is only listening while it has an entry here, so the tests that + /// run alongside it — on other threads, in the same process — do not put + /// their own output in its list. + static LISTENING: OnceLock>>> = OnceLock::new(); + + fn listening() -> &'static Mutex>> { + LISTENING.get_or_init(Default::default) + } + + struct Capture; impl LookupSpan<'a>> tracing_subscriber::Layer for Capture { fn on_event(&self, event: &TracingEvent<'_>, _ctx: Context<'_, S>) { @@ -995,6 +1007,11 @@ mod tests { return; } + let mut listening = listening().lock().expect("capture poisoned"); + let Some(lines) = listening.get_mut(&thread::current().id()) else { + return; + }; + struct Message(String); impl field::Visit for Message { fn record_debug(&mut self, f: &field::Field, value: &dyn std::fmt::Debug) { @@ -1006,18 +1023,40 @@ mod tests { let mut message = Message(String::new()); event.record(&mut message); - self.0.lock().expect("capture poisoned").push(message.0); + lines.push(message.0); } } - let capture = Capture::default(); - let lines = capture.0.clone(); - // No target filter: the layer takes every `DEBUG` event and the assertions - // below name the exact lines, so a filter would only be another thing able - // to make the test pass by seeing nothing. - tracing::subscriber::with_default(tracing_subscriber::registry().with(capture), f); + // Installed once, for the whole test binary, and globally rather than for + // this thread alone. `tracing` decides whether a callsite is enabled the + // first time that callsite is reached and caches the answer for the whole + // process, resolving it against the subscriber of the thread that got there + // first. So with a thread-local capture, another test reaching the same + // `debug!` first cached "disabled" and this thread heard nothing. A global + // capture is every thread's subscriber, so the answer is the same whoever + // reaches the callsite first. + static INSTALLED: OnceLock<()> = OnceLock::new(); + INSTALLED.get_or_init(|| { + // No target filter: the layer takes every `DEBUG` event and the + // assertions below name the exact lines, so a filter would only be + // another thing able to make the test pass by seeing nothing. + tracing::subscriber::set_global_default(tracing_subscriber::registry().with(Capture)) + .expect("no other subscriber is installed by these tests"); + }); + + let id = thread::current().id(); + listening() + .lock() + .expect("capture poisoned") + .insert(id, Vec::new()); + + f(); - lines.lock().expect("capture poisoned").clone() + listening() + .lock() + .expect("capture poisoned") + .remove(&id) + .expect("this thread was listening") } /// A step's output is logged with the canister name, because under `--debug` the From 0bc9bc88188ffb4f9733f67e04c25fb9490d9151 Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 12:58:15 +0000 Subject: [PATCH 13/14] no-mistakes(document): note --debug canister prefix in changelog; run cargo fmt --- .claude/testing.md | 5 +++++ CHANGELOG.md | 1 + crates/icp-cli/tests/build_tests.rs | 16 ++++++++++++---- crates/icp-cli/tests/sync_tests.rs | 16 ++++++++++++---- 4 files changed, 30 insertions(+), 8 deletions(-) diff --git a/.claude/testing.md b/.claude/testing.md index 5c0f6ba96..7396b9eba 100644 --- a/.claude/testing.md +++ b/.claude/testing.md @@ -8,6 +8,11 @@ Tests are split between unit tests (in modules) and integration tests: - Use `assert_cmd` for CLI assertions and `predicates` for output matching - Use `serial_test` with file locks for tests that share resources (network ports) - Some tests launch local networks and require available ports +- Only one process-global `tracing` subscriber may be installed per test binary. In `icp-cli`'s + unit tests that is `events.rs::tests::captured_debug_lines`, which captures `debug!` lines; + installing a second one panics it. It has to be global rather than thread-local because + `tracing` decides whether a callsite is enabled the first time any thread reaches it and + caches that answer for the process. ## Mock Helpers diff --git a/CHANGELOG.md b/CHANGELOG.md index 55879de88..8afc44b60 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,7 @@ bump. Currently experimental: project bundling, project dependencies * feat: `script` build steps now receive `ICP_CLI_ENVIRONMENT`, the name of the environment the canisters are being built for, so a build can vary by environment the way a sync step already could. * feat: `icp completions ` prints a shell completion script for `bash`, `zsh`, `fish`, `powershell`, or `elvish` to stdout. See the [installation guide](docs/guides/installation.md#shell-completions) for where to put it. * fix: `icp canister logs` output formats are corrected. `--json` now emits machine-readable JSON and the default emits the human-readable lines (the two were swapped), and `--follow --json` emits newline-delimited JSON, one record per line, streamed as each record arrives. This is breaking for scripts: parsing the default output as JSON now requires `--json`, and consumers of `--follow --json` must read one JSON object per line. +* fix: under `--debug`, each line of a build or sync step's output is now prefixed with the canister that produced it (`[canister-a] compiling`), the way the progress bars label it without `--debug`. Previously the lines were unattributed, so canisters built in parallel interleaved into a stream you could not read. # v1.3.0 diff --git a/crates/icp-cli/tests/build_tests.rs b/crates/icp-cli/tests/build_tests.rs index 3c54232fd..4ab22f4b8 100644 --- a/crates/icp-cli/tests/build_tests.rs +++ b/crates/icp-cli/tests/build_tests.rs @@ -502,8 +502,12 @@ fn build_multiple_canisters() { .assert() .success() .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::events: [canister-a] building canister-a")) - .stderr(contains("DEBUG icp::events: [canister-b] building canister-b")) + .stderr(contains( + "DEBUG icp::events: [canister-a] building canister-a", + )) + .stderr(contains( + "DEBUG icp::events: [canister-b] building canister-b", + )) .stderr(contains("DEBUG icp::events: [canister-c] building canister-c").not()); } @@ -559,7 +563,11 @@ fn build_all_canisters_in_environment() { .success() .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::events: [canister-a] building canister-a")) - .stderr(contains("DEBUG icp::events: [canister-b] building canister-b")) + .stderr(contains( + "DEBUG icp::events: [canister-a] building canister-a", + )) + .stderr(contains( + "DEBUG icp::events: [canister-b] building canister-b", + )) .stderr(contains("DEBUG icp::events: [canister-c] building canister-c").not()); // not in test-env } diff --git a/crates/icp-cli/tests/sync_tests.rs b/crates/icp-cli/tests/sync_tests.rs index 75c8d165a..6b429c6a5 100644 --- a/crates/icp-cli/tests/sync_tests.rs +++ b/crates/icp-cli/tests/sync_tests.rs @@ -388,8 +388,12 @@ async fn sync_multiple_canisters() { .success() .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: ["canister-a", "canister-b"]"#)) - .stderr(contains("DEBUG icp::events: [canister-a] syncing canister-a")) - .stderr(contains("DEBUG icp::events: [canister-b] syncing canister-b")) + .stderr(contains( + "DEBUG icp::events: [canister-a] syncing canister-a", + )) + .stderr(contains( + "DEBUG icp::events: [canister-b] syncing canister-b", + )) .stderr(contains("DEBUG icp::events: [canister-c] syncing canister-c").not()); } @@ -862,7 +866,11 @@ async fn sync_all_canisters_in_environment() { .stderr(contains("Syncing canisters")) .stderr(contains(r#"canisters: []"#)) .stderr(contains(r#"environment: Some("test-env")"#)) - .stderr(contains("DEBUG icp::events: [canister-a] syncing canister-a")) - .stderr(contains("DEBUG icp::events: [canister-b] syncing canister-b")) + .stderr(contains( + "DEBUG icp::events: [canister-a] syncing canister-a", + )) + .stderr(contains( + "DEBUG icp::events: [canister-b] syncing canister-b", + )) .stderr(contains("DEBUG icp::events: [canister-c] syncing canister-c").not()); // not in test-env } From 91f369b16c3c69a0adb3941b42a445a64b69351e Mon Sep 17 00:00:00 2001 From: Raymond Khalife Date: Tue, 18 Aug 2026 20:27:57 +0300 Subject: [PATCH 14/14] bump h2 --- Cargo.lock | 36 ++++++++++++++++++------------------ 1 file changed, 18 insertions(+), 18 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index bad15fc21..26d724e14 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -120,7 +120,7 @@ version = "1.1.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "40c48f72fd53cd289104fc64099abca73db4166ad86ea0b4341abe65af83dadc" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -131,7 +131,7 @@ checksum = "291e6a250ff86cd4a820112fb8898808a366d8f9f58ce16d1f538353ad55747d" dependencies = [ "anstyle", "once_cell_polyfill", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -1047,7 +1047,7 @@ dependencies = [ "cap-primitives", "cap-std", "io-lifetimes 3.0.1", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -1064,7 +1064,7 @@ dependencies = [ "maybe-owned", "rustix", "rustix-linux-procfs", - "windows-sys 0.61.2", + "windows-sys 0.60.2", "winx", ] @@ -2024,7 +2024,7 @@ dependencies = [ "libc", "option-ext", "redox_users 0.5.2", - "windows-sys 0.61.2", + "windows-sys 0.59.0", ] [[package]] @@ -2274,7 +2274,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "39cab71617ae0d63f51a36d69f866391735b51691dbda63cf6f96d042b63efeb" dependencies = [ "libc", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -2976,9 +2976,9 @@ dependencies = [ [[package]] name = "h2" -version = "0.4.15" +version = "0.4.16" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6cb093c84e8bd9b188d4c4a8cb6579fc016968d14c99882163cd3ff402a4f155" +checksum = "a9f37a958b41b3b19ee2707c06439c0e9e547e847223eb791ecb0cb821c65e27" dependencies = [ "atomic-waker", "bytes", @@ -4878,7 +4878,7 @@ version = "0.50.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.59.0", ] [[package]] @@ -6212,7 +6212,7 @@ dependencies = [ "errno", "libc", "linux-raw-sys", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -6279,7 +6279,7 @@ dependencies = [ "security-framework 3.7.0", "security-framework-sys", "webpki-root-certs", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -6932,7 +6932,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "52d1cfed4120b4d927bf7c0f86d2087a4a7d6027c906d9f9d525a80573b9be51" dependencies = [ "libc", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -6961,7 +6961,7 @@ dependencies = [ "cfg-if", "libc", "psm", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -7144,7 +7144,7 @@ dependencies = [ "getrandom 0.4.3", "once_cell", "rustix", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -7184,7 +7184,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "230a1b821ccbd75b185820a1f1ff7b14d21da1e442e22c0863ea5f08771a8874" dependencies = [ "rustix", - "windows-sys 0.61.2", + "windows-sys 0.59.0", ] [[package]] @@ -7641,7 +7641,7 @@ checksum = "f2f6fb2847f6742cd76af783a2a2c49e9375d0a111c7bef6f71cd9e738c72d6e" dependencies = [ "memoffset", "tempfile", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -8372,7 +8372,7 @@ version = "0.1.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c2a7b1c03c876122aa43f3020e6c3c3ee5c05081c9a00739faf7503aeba10d22" dependencies = [ - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -8770,7 +8770,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7d6f32a0ff4a9f6f01231eb2059cc85479330739333e0e58cadf03b6af2cca10" dependencies = [ "cfg-if", - "windows-sys 0.61.2", + "windows-sys 0.59.0", ] [[package]]