diff --git a/.claude/CLAUDE.md b/.claude/CLAUDE.md index edb1cec9b..d196cee0c 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`, `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 9f3a45690..ae45cdb0b 100644 --- a/.claude/architecture.md +++ b/.claude/architecture.md @@ -77,6 +77,56 @@ 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`, +`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)`. 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 + reports events. To check that this still holds: + + ```bash + 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 + `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 + 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. +- 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. + +Operations are unit-tested by running them against `RecordingSink` and asserting on the +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 Anonymous usage telemetry implementation. User-facing documentation is in `docs/telemetry.md`. 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/Cargo.lock b/Cargo.lock index 1d9ca596b..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", @@ -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", @@ -3726,6 +3727,7 @@ dependencies = [ "ic-utils", "icp", "icp-canister-interfaces", + "icp-events", "icrc-ledger-types", "indicatif", "indoc", @@ -3769,6 +3771,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" @@ -3782,6 +3793,7 @@ dependencies = [ "hex", "ic-agent", "icp-canister-interfaces", + "icp-events", "snafu", "tokio", "wasmtime", @@ -4866,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]] @@ -6200,7 +6212,7 @@ dependencies = [ "errno", "libc", "linux-raw-sys", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -6267,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]] @@ -6920,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]] @@ -6949,7 +6961,7 @@ dependencies = [ "cfg-if", "libc", "psm", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -7132,7 +7144,7 @@ dependencies = [ "getrandom 0.4.3", "once_cell", "rustix", - "windows-sys 0.61.2", + "windows-sys 0.52.0", ] [[package]] @@ -7172,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]] @@ -7629,7 +7641,7 @@ checksum = "f2f6fb2847f6742cd76af783a2a2c49e9375d0a111c7bef6f71cd9e738c72d6e" dependencies = [ "memoffset", "tempfile", - "windows-sys 0.61.2", + "windows-sys 0.60.2", ] [[package]] @@ -8360,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]] @@ -8758,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]] 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/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 b2a1fe4ca..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}; @@ -21,9 +22,10 @@ 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, + build::build_many, candid_compat::check_candid_compatibility_many, create::{CreateFunding, CreateOperation, CreateTarget}, install::{install_many, resolve_install_mode_and_status}, @@ -32,7 +34,6 @@ use crate::{ sync::sync_many, }, options::{IdentityOpt, arg_struct_change_help}, - progress::{ProgressManager, ProgressManagerSettings}, }; /// Deploy a project to an environment @@ -182,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?; @@ -231,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 }); @@ -325,7 +325,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 +335,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 +385,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 +398,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?; @@ -498,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..1eb45a671 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,27 +193,25 @@ 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, - 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?; + 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}"), + ) + .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 new file mode 100644 index 000000000..e3e83a4b4 --- /dev/null +++ b/crates/icp-cli/src/events.rs @@ -0,0 +1,1170 @@ +//! Rendering [`icp_events`] onto the terminal. +//! +//! 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, VecDeque}, + sync::{Arc, Mutex}, + time::Duration, +}; + +use icp_events::{Event, EventSink, Outcome, Reporter, TaskId, TaskKind}; +use indicatif::{MultiProgress, ProgressBar, ProgressDrawTarget, ProgressStyle}; +use itertools::Itertools; +use tracing::debug; + +/// 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 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))) +} + +/// 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, + /// 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, + /// 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) { + // 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`. + // 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 } => { + let bar = ProgressBar::new(total).with_style(byte_style()); + 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), + } + } + // Spinners and multi-step bars are the same bar; only the message + // differs, and steps build a richer one. + _ => { + let bar = ProgressBar::new_spinner().with_style(running_style()); + let bar = match &prefix { + Some(prefix) => bar.with_prefix(prefix.clone()), + None => bar, + }; + + let bar = self.multi.add(bar); + bar.enable_steady_tick(STEADY_TICK); + + BarState { + bar, + prefix, + 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(), + } + } + + /// 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); + } + } + + /// 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 { + 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 } => { + self.with_bar(id, |state| state.bar.set_message(message)); + } + + Event::TaskPosition { id, position } => { + self.with_bar(id, |state| state.bar.set_position(position)); + } + + 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 } => { + // 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); + Self::redraw_step(state); + }); + } + + Event::StepFinished { id, .. } => { + self.with_bar(id, |state| 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}"), + }, + + _ => {} + } + } +} + +/// Proof that the events path draws what the code it replaced drew. +/// +/// 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 { + use super::*; + use futures::executor::block_on; + use indicatif::TermLike; + use std::io; + + /// A terminal that remembers what was written to it. + #[derive(Debug, Clone, Default)] + pub(super) 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] = ['✶', '✸', '✹', '✺', '✷']; + + /// 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. 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; + /// - 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 + .lock() + .expect("writes poisoned") + .iter() + .map(|frame| strip_ansi(frame)) + .filter(|frame| !frame.trim().is_empty()) + .map(|frame| { + frame + .chars() + .map(|c| { + if ANIMATION_GLYPHS.contains(&c) { + '~' + } else { + c + } + }) + .collect::() + }) + .filter(|frame| !frame.trim_end().ends_with('~')) + .collect(); + frames.dedup(); + frames + } + + /// 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()) + .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 { + 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(()) + } + } + + pub(super) fn recording_target(term: &RecordingTerm) -> ProgressDrawTarget { + ProgressDrawTarget::term_like(Box::new(term.clone())) + } + + fn new_reporter(term: &RecordingTerm) -> Reporter { + Reporter::new(Arc::new(IndicatifSink::with_draw_target(recording_target( + term, + )))) + } + + /// 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>, + 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() + } + + /// What `ProgressManager` drew for a canister that installed successfully. + const EXPECTED_SUCCESS: [&str; 3] = [ + "[backend] ~ Installing...", + "[backend] ~ Installed successfully", + "[backend] ✔ Installed successfully", + ]; + + #[test] + fn a_success_draws_the_frames_the_progress_manager_drew() { + assert_eq!( + frames_for::(Ok(()), "Installed successfully", |e| e.clone()), + EXPECTED_SUCCESS + ); + } + + /// 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_frames_the_progress_manager_drew() { + let message = "Failed to install canister: boom"; + + assert_eq!( + frames_for(Err("boom".to_string()), "unused", |_| message.to_string()), + EXPECTED_FAILURE + ); + } + + /// `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_what_finish_with_message_drew() { + let term = RecordingTerm::default(); + new_reporter(&term) + .task(TaskKind::Spinner, "backend") + .skip("Skipped (not an upgrade)"); + + assert_eq!(term.frames(), ["[backend] Skipped (not an upgrade)"]); + } + + /// 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 reporter = new_reporter(&term); + for name in ["frontend", "backend"] { + reporter.task(TaskKind::Spinner, name).skip("done"); + } + + assert_eq!(term.frames(), ["[frontend] done", "[backend] done"]); + } + + /// 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"); + for position in positions { + task.position(*position); + } + if finish { + task.succeed("done"); + return term.timeless_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 line `create_transfer_progress_bar` drew for a transfer at rest. + /// + /// `{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_transfer_bars_line() { + assert_eq!( + 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 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: impl AsRef) -> String { + let frame = frame.as_ref(); + 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(), + }) + } +} + +#[cfg(test)] +mod tests { + use super::{ + rendering::{RecordingTerm, recording_target}, + *, + }; + + /// 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"); + } + + /// 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_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, + 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); + + let frames = term.frames(); + assert!( + frames + .iter() + .any(|frame| frame.contains("[backend]") + && frame.contains("Skipped (not an upgrade)")), + "frames: {frames:?}" + ); + } + + /// `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); + + // 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]")), + "frames: {frames:?}" + ); + } + + /// 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::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}; + + /// 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>) { + if *event.metadata().level() != Level::DEBUG { + 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) { + if f.name() == "message" { + self.0 = format!("{value:?}"); + } + } + } + + let mut message = Message(String::new()); + event.record(&mut message); + lines.push(message.0); + } + } + + // 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(); + + 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 + /// 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(); + + // 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..2fdd6493a 100644 --- a/crates/icp-cli/src/main.rs +++ b/crates/icp-cli/src/main.rs @@ -17,10 +17,10 @@ mod artifacts; mod commands; mod complete; mod dist; +mod events; mod logging; pub(crate) mod operations; mod options; -mod progress; mod telemetry; mod version; 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/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/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..7aabba21c 100644 --- a/crates/icp-cli/src/operations/mod.rs +++ b/crates/icp-cli/src/operations/mod.rs @@ -10,8 +10,12 @@ 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; 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/snapshot_transfer.rs b/crates/icp-cli/src/operations/snapshot_transfer.rs index 24a6388de..b08c869fa 100644 --- a/crates/icp-cli/src/operations/snapshot_transfer.rs +++ b/crates/icp-cli/src/operations/snapshot_transfer.rs @@ -19,7 +19,7 @@ use icp::{ fs::lock::{DirectoryStructureLock, LWrite, LockError, PathsAccess}, prelude::*, }; -use indicatif::{ProgressBar, ProgressStyle}; +use icp_events::Task; use serde::{Deserialize, Serialize}; use snafu::{ResultExt, Snafu}; use tokio::{ @@ -424,19 +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( - 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_prefix(label.to_string()); - pb -} - /// Read snapshot metadata from a canister. pub async fn read_snapshot_metadata( agent: &Agent, @@ -513,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); @@ -545,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(); @@ -611,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(()) @@ -663,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) @@ -690,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(); @@ -742,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 { @@ -902,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/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..7e4ccb8ed 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,7 +29,7 @@ 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 @@ -39,7 +43,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 +52,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 +67,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 +80,10 @@ 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. pub(crate) async fn sync_many( syncer: Arc, agent: Agent, @@ -88,14 +92,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 +127,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 +165,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 +197,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 +213,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/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 deleted file mode 100644 index 0a0795991..000000000 --- a/crates/icp-cli/src/progress.rs +++ /dev/null @@ -1,334 +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"; - -// 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 { - let pb = self.create_independent_progress_bar(); - pb.set_prefix(format!("[{canister_name}]")); - pb - } - - 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 - ))); - - // Auto-tick spinner - pb.enable_steady_tick(Duration::from_millis(120)); - - 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(_) => (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)), - }; - - 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-cli/tests/build_tests.rs b/crates/icp-cli/tests/build_tests.rs index c2e89fbf0..4ab22f4b8 100644 --- a/crates/icp-cli/tests/build_tests.rs +++ b/crates/icp-cli/tests/build_tests.rs @@ -502,9 +502,13 @@ 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: [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 +563,11 @@ 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: [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 31f72ef48..6b429c6a5 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::progress: 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::progress: syncing").not()), + .and(contains("] syncing").not()), ); } @@ -387,9 +388,13 @@ 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: [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 +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::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: [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 } 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..0b70ef169 --- /dev/null +++ b/crates/icp-events/src/cancel.rs @@ -0,0 +1,332 @@ +use std::{ + collections::HashMap, + 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, + 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 { + /// 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 waiters = std::mem::take( + &mut self + .inner + .waiters + .lock() + .expect("cancel token poisoned") + .wakers, + ); + for waker in waiters.into_values() { + 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(), + 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 + /// 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, + /// Which slot in [`Waiters`] holds this future's waker, once it has parked. + registration: Option, +} + +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) { + // `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(()); + } + + // 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); + } + } + + 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() { + 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 + ); + } + + /// 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); + } +} 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..b7cac3c66 --- /dev/null +++ b/crates/icp-events/src/lib.rs @@ -0,0 +1,64 @@ +//! 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. +//! +//! 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 +//! 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 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 new file mode 100644 index 000000000..d1ef7542b --- /dev/null +++ b/crates/icp-events/src/reporter.rs @@ -0,0 +1,697 @@ +use std::{ + fmt, + future::Future, + sync::{ + Arc, + atomic::{AtomicU64, Ordering}, + }, +}; + +use crate::{ + cancel::CancelToken, + event::{Event, NoticeLevel, Outcome, TaskId, TaskKind}, + output::{OutputWriter, RecordedStep, StepLog}, + 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, + log: Arc::new(StepLog::default()), + } + } +} + +/// 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, + log: Arc, +} + +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); + + let title = title.into(); + self.log.begin(title.clone()); + + self.reporter.emit(Event::StepStarted { + id: self.id, + index, + title, + }); + } + + /// Report a line of output from the step in progress. + pub fn step_output(&self, line: impl 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. + /// + /// # 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()), + }, + ] + ); + } + + /// 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(); + + 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); + } +} 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/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-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..3a5f48621 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 { @@ -113,13 +113,13 @@ 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 { 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>(()) @@ -128,13 +128,13 @@ 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 { 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,