refactor: report progress through a new icp-events crate instead of the terminal - #709
refactor: report progress through a new icp-events crate instead of the terminal#709raymondk wants to merge 14 commits into
Conversation
f754450 to
f8bf02e
Compare
There was a problem hiding this comment.
Pull request overview
Introduces an event-based progress abstraction to decouple CLI operations from terminal rendering.
Changes:
- Adds
icp-eventswith events, reporting, recording, and cancellation APIs. - Adds an
indicatifevent sink with rendering-equivalence tests. - Migrates four deploy operations to
Reporterwith event-sequence tests.
Reviewed changes
Copilot reviewed 21 out of 22 changed files in this pull request and generated no comments.
Show a summary per file
| File | Description |
|---|---|
.claude/CLAUDE.md |
Documents the new crate. |
.claude/architecture.md |
Documents progress architecture. |
Cargo.toml |
Registers icp-events. |
Cargo.lock |
Locks the new crate. |
crates/icp-events/Cargo.toml |
Configures crate dependencies. |
crates/icp-events/src/cancel.rs |
Implements cancellation tokens. |
crates/icp-events/src/event.rs |
Defines the event model. |
crates/icp-events/src/lib.rs |
Exposes the public API. |
crates/icp-events/src/reporter.rs |
Implements reporters and tasks. |
crates/icp-events/src/sink.rs |
Implements event sinks. |
crates/icp-cli/Cargo.toml |
Adds the crate dependency. |
crates/icp-cli/src/commands/deploy.rs |
Supplies reporters to operations. |
crates/icp-cli/src/events.rs |
Renders events with indicatif. |
crates/icp-cli/src/main.rs |
Registers the events module. |
crates/icp-cli/src/operations/binding_env_vars.rs |
Migrates environment-variable progress. |
crates/icp-cli/src/operations/candid_compat.rs |
Migrates compatibility-check progress. |
crates/icp-cli/src/operations/install.rs |
Migrates installation progress. |
crates/icp-cli/src/operations/mod.rs |
Registers test support. |
crates/icp-cli/src/operations/settings.rs |
Migrates settings progress. |
crates/icp-cli/src/operations/snapshot_transfer.rs |
Reuses byte-bar styling. |
crates/icp-cli/src/operations/test_support.rs |
Adds shared operation fixtures. |
crates/icp-cli/src/progress.rs |
Exposes shared progress styles. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
…tions Progress reporting is what welds `crates/icp-cli/src/operations/` to the binary: six of those files import `crate::progress` and a seventh drives `indicatif` directly. This inverts the dependency so the rest of the crate split can proceed. New crate `crates/icp-events` expresses progress and user-facing notices as data: `Event`, `Reporter`, `Task`, `EventSink`, `CancelToken`. It depends only on serde and futures — not on `icp`, not on an async runtime, and on nothing terminal-shaped. `TaskKind` carries the three shapes the CLI uses today (spinner, multi-step with streamed command output, byte position) and `Event::Notice` carries the user-facing `info!`/`warn!`/`error!` output, so converting those later needs no redesign. `crates/icp-cli/src/events.rs` adds `IndicatifSink`, the one place that knows about both events and `indicatif`. It takes its styles and tick interval from `crate::progress` so the two renderers cannot drift while both exist. `install.rs`, `settings.rs`, `binding_env_vars.rs` and `candid_compat.rs` now take a `&Reporter` instead of `debug: bool`. `progress.rs` stays for `build.rs`, `sync.rs` and `snapshot_transfer.rs`, which a separate change owns. The event model is deliberately not semver-stable: `publish = false`, `0.x`, all enums `#[non_exhaustive]`, `TaskKind` closed. Events do not drive `--json`.
f8bf02e to
2cf993d
Compare
`ProgressBar::enable_steady_tick` spawns a thread that draws a frame immediately, so a prefix set after that call races the first tick. On a machine slow enough to lose that race the bar drew a bare spinner before its label appeared, which made the rendering-equivalence tests fail on macOS while passing on Linux and Windows. Both renderers had the same ordering, so both could produce the stray frame; build each bar fully styled and labelled before it is shown and, for spinners, before the ticker starts.
Finishes the progress inversion. The three operations left on the old renderer now report through `icp-events`, both `crates/icp` ports stop taking a terminal-shaped channel, and `progress.rs` is gone. - `icp-events` gains `OutputWriter`: a cheap, cloneable handle for the lines a running step produces. It reports each line as a `StepOutput` event and keeps it in the task's step log, so an operation can replay the failing step once the bars are down. That replaces the tokio channel plus the background drain task that `MultiStepProgressBar` needed, and with it the `end_step().await` that only existed to wait for that drain. - `Build::build` and `Synchronize::sync` — and the script, prebuilt, wasm-resolve, plugin and script-runner paths under them — take `Option<OutputWriter>` instead of `Option<Sender<String>>`. The sync plugin runtime reports lines directly rather than `try_send`-ing them at a bounded channel, so a noisy plugin no longer silently drops output. - `snapshot_transfer` reports byte positions as `TaskKind::Bytes` progress, resume offsets included, and no longer builds its own bar. - `build_many`, `sync_many` and `create_bundle` take a `Reporter`; their `debug: bool` becomes `all_step_output`, which is the only thing that flag still decided once hiding moved to the reporter. `indicatif` is now confined to `events.rs`, which is also where the styles live. The two bespoke spinners in `canister migrate-id` and `identity link web` still build their own bars; they never used `progress.rs` and their look does not fit the shared model. The old renderers are gone, so the rendering tests pin the frames they drew as literals, captured from them before they were deleted.
The prose still said the inversion was partway done, with `build.rs`, `sync.rs` and `snapshot_transfer.rs` rendering directly and `progress.rs` awaiting removal. All of that has now shipped, so describe the end state: operations report events, `indicatif` is confined to `events.rs` bar the two bespoke spinners in `commands/`, and `OutputWriter` is how a library hands back the lines a step produced. Also adds the operation-level byte-progress test for a resumed transfer, and drops two `too_many_arguments` allows this repo's threshold of 12 makes unnecessary.
Under `--debug` the progress bars are hidden, so the `debug!` line the sink logs for each step-output event was the only record of a build's output - and it carried just the line. Canisters build in parallel, so several of them interleaved into a stream with nothing saying which canister printed what. The bars themselves have always shown the name in their prefix, so this was an inconsistency between the two paths rather than a missing feature. `BarState` now keeps the prefix it gave the bar, and the log line reuses it, so `[backend] compiling` reads the same way the bar does. Byte tasks label their bars undecorated and keep doing so here; they report no step output today, so that only settles the shape. The prefix is kept at construction rather than read back off the bar, and a line whose task is unknown - or which has no label - is still logged, bare, rather than dropped for want of a prefix. Verified on a real parallel build: five canisters under `--debug` produced 20 output lines, every one attributed to the canister that emitted it, with the canister changing between every consecutive pair.
raymondk
left a comment
There was a problem hiding this comment.
Review focused on test redundancy and comment noise. The design is sound and everything passes locally (cargo test -p icp-events -p icp-cli --bins: 40 + 105 pass; cargo clippy --all-targets clean). Inline comments cover the file-specific items; the cross-cutting ones are below.
1. A large part of the new crate has no callers
This is the biggest "unnecessary" item. Grepping the workspace outside crates/icp-events/src:
| API | Callers |
|---|---|
cancel.rs — CancelToken, Cancelled, run_until, Reporter::with_cancel_token, cancel_token() |
none |
Event::Notice + NoticeLevel + Reporter::notice/info/warn/error |
none — nothing constructs a Notice; the sink arm is an admitted placeholder |
Reporter::discard() / DiscardSink |
none |
Task::step_output |
none (call sites all use task.output().line()) |
RecordingSink::take |
none |
MAX_RECORDED_LINES_PER_STEP as pub |
internal only |
cancel.rs is the costly one: 332 lines including a keyed waker registry with drop-time deregistration, plus 10 tests, none of which any operation exercises. Its subtleties (re-poll waker replacement, re-check under lock) are exactly the kind of thing that rots when unexercised.
My suggestion is to cut cancel.rs and the Notice/discard surface from this increment and land each with the change that needs it. If you'd rather keep the model complete up front, that's a defensible call — but then it's worth saying so in the PR body, because as it stands a reviewer can't tell "planned" from "orphaned".
2. Six copies of the same ordering test
operations/build.rs, sync.rs, install.rs, candid_compat.rs, binding_env_vars.rs, settings.rs all assert task_labels(...) == [frontend, backend], each ~25 lines of call-site boilerplate. Plus events.rs's bars_are_drawn_in_the_order_the_canisters_were_given and reporter.rs's task_ids_are_handed_out_in_creation_order for the same property one layer down. The invariant is per-call-site so it isn't pure duplication, but eight tests for "don't move reporter.task() inside the async block" is a lot — two (one steps-op, one spinner-op) would cover the regression at a fraction of the size. Details inline on operations/build.rs.
3. The same fact explained three times
Two subtle facts each get explained in three places, which means three places to update when either changes:
- ANSI/colour detection:
strip_ansi's doc,RecordingTerm::frames' 15-line doc, andnormalization_strips_the_colour_codes_a_terminal_would_add's doc. - The
enable_steady_tickrace:IndicatifSink::start,a_spinner_is_labelled_before_its_first_tick, and.claude/architecture.md.
One site should carry each explanation; the others can point at it.
Separately, this comment is duplicated verbatim in five files:
// 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.
It's a good comment — it just doesn't need to be five comments. One in test_support.rs or the architecture doc, referenced from the call sites, would do.
What's good
The frame-golden approach in mod rendering is the right call for a refactor that deletes its own baseline; capturing the literal pre-inversion output is far more convincing than eyeballing it. step_replay.rs and its tests are tight — five tests, no overlap, each pinning one formatting rule. The Task drop-closes-neutrally guarantee is the correct invariant and is tested at the right level. And the --debug canister-prefix fix is a genuine user-visible improvement that the CHANGELOG entry describes plainly.
| /// 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 { |
There was a problem hiding this comment.
Nothing outside this crate uses CancelToken, Cancelled, run_until, Reporter::with_cancel_token, or cancel_token() — the module's own tests are its only consumers.
That's 332 lines including a keyed waker registry with drop-time deregistration, plus 10 tests, for machinery no operation exercises. The subtle parts (waker replacement on re-poll, the re-check under the lock) are exactly what rots when nothing calls them.
I'd land this with the increment that actually needs cancellation.
| } | ||
|
|
||
| /// A reporter that throws everything away. | ||
| pub fn discard() -> Self { |
There was a problem hiding this comment.
Reporter::discard() and DiscardSink have no callers outside the crate. The two tests that cover them (a_discarding_reporter_still_works here, discard_sink_keeps_nothing in sink.rs) are both assertion-free.
| } | ||
|
|
||
| /// Emit a user-facing message that does not belong to any task. | ||
| pub fn notice(&self, level: NoticeLevel, message: impl Into<String>) { |
There was a problem hiding this comment.
notice/info/warn/error — and Event::Notice / NoticeLevel behind them — have no callers. Nothing in the workspace constructs a Notice; events.rs has a receiving arm that the comment there describes as a placeholder for a separate work item.
Five methods, an enum, and two tests for a path that doesn't exist yet. Worth landing with the conversion that uses it.
| } | ||
|
|
||
| /// Report a line of output from the step in progress. | ||
| pub fn step_output(&self, line: impl Into<String>) { |
There was a problem hiding this comment.
step_output has no callers outside this crate's tests — every real call site goes through task.output().line(). It's a one-line convenience wrapper; probably fine to drop until something wants it.
| /// 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() { |
There was a problem hiding this comment.
This test, and sinks_are_usable_from_several_threads in sink.rs, assert Send/Sync and that Mutex works. Both are compile-time properties — a fn _assert_send<T: Send>() {} plus a call site says the same thing without spawning threads, and fails at compile time rather than at test time.
| } | ||
|
|
||
| #[cfg(test)] | ||
| mod reporting_tests { |
There was a problem hiding this comment.
A second test module next to the existing mod tests — the new tests could just go in tests. It's the only file in the PR that splits them.
| /// 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; |
There was a problem hiding this comment.
task_labels is imported inside the function body here, while every sibling test module imports it at the top with the rest of test_support. Worth making consistent.
There was a problem hiding this comment.
Resolved by deletion rather than by moving the import: this is one of the six near-identical tasks_are_started_in_the_order_the_canisters_were_given tests, and per your other comment I kept two — build.rs (a steps operation) and install.rs (a spinner operation) — and dropped the rest, this one included.
So there is no longer an inconsistent inline import here. The two survivors both import from test_support at the top of their module with everything else.
| ctx.artifacts.clone(), | ||
| &ctx.dirs.package_cache()?, | ||
| &indicatif_reporter(ctx.debug), | ||
| ctx.debug, |
There was a problem hiding this comment.
These two adjacent arguments are both derived from ctx.debug but mean opposite things — hide the bars vs. replay more output on failure. Same shape in deploy.rs and commands/sync.rs.
The rename to all_step_output helps at the definition; the call site still reads as ctx.debug twice, which is easy to get wrong when someone edits this later.
| // 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 |
There was a problem hiding this comment.
This comment (and the matching one on l.131) restates the line below it — let stdio = stdio.clone(); already says it clones the writer for the task.
Pre-existing, but the PR touches these exact lines, so it's a free cleanup.
|
|
||
| // Update progress bar to show frontier position | ||
| progress_bar.set_position(progress.blob_progress(blob_type).frontier); | ||
| // Report the frontier position |
There was a problem hiding this comment.
// Report the frontier position restates task.position(progress.blob_progress(blob_type).frontier) directly below it. The companion comment on the initial position ("a resumed download starts partway in") earns its place because it explains why; this one doesn't add anything.
Why
Progress reporting is what welded
crates/icp-cli/src/operations/to the binary: six of those files importedcrate::progress, a seventh droveindicatifdirectly, and twocrates/icpports took atokio::sync::mpsc::Sender<String>that only existed because the binary had a progress bar to feed. Nothing else in the crate split can start until that is inverted, so it goes first — and it lands as one change rather than a partial one, so the tree is never half-converted.What
New crate
crates/icp-events— progress and user-facing notices as data. Depends on serde and futures only; not onicp, not on an async runtime, not on anything terminal-shaped (indicatif,dialoguer,clap,console).Event—TaskStarted/TaskMessage/TaskPosition/TaskFinished,StepStarted/StepOutput/StepFinished, andNotice { level, message }TaskKind— closed enum carrying the three shapes that exist:Spinner,Steps { output_label },Bytes { total }Reporter/Task—Task::run(fut, success, error)replacesProgressManager::execute_with_progress. A droppedTaskstill emitsTaskFinished { Neutral }, so an early return cannot leave a sink holding a bar that spins forever.OutputWriter— a cheap, cloneable handle for the lines a running step produces. Each line becomes anEvent::StepOutputand is kept in the task's step log (capped atMAX_RECORDED_LINES_PER_STEP), so an operation that fails can replay the failing step once the bars are down.EventSink,DiscardSink,RecordingSink,CancelTokencrates/icp-cli/src/events.rs—IndicatifSink, now the only place in the workspace that knows aboutindicatif, and where the styles live.Every operation converted.
install.rs,settings.rs,binding_env_vars.rs,candid_compat.rs,build.rs,sync.rs,snapshot_transfer.rsandbundle.rstake a&Reporter; none takesdebug: bool. The commands that drew their own bars —deploy.rs,network/start.rs,network/update.rs,canister snapshot upload/download— go through the reporter too.build_many/sync_many/create_bundlekeep one bool, renamedall_step_output: replaying every step of a failure rather than only the failing one is the only thingdebugstill decided once bar-hiding moved into the reporter.Both port signatures changed.
Build::buildandSynchronize::sync— and the script, prebuilt, wasm-resolve, plugin and script-runner paths beneath them — takeOption<OutputWriter>instead ofOption<Sender<String>>.crates/icpgains no terminal-shaped dependency; it depends onicp-events, which is serde + futures.Two things fall out of that:
MultiStepProgressBar's channel plus the background task that drained it are gone, and with themend_step().await, which existed only to wait for that drain. Recording is now synchronous.try_sendon a bounded channel, so a noisy plugin silently dropped output when the renderer fell behind. It no longer can.progress.rsis deleted. The compiler was the gate, as the architecture note asked: it was removed andcargo check -p icp-cli --all-targetshad to come back clean.The two macOS failures
events::rendering_equivalencefailed onmacos-15only, with an extra bare" ~ "frame captured before the[backend]prefix appeared.Not the rebase, and not a new defect:
ProgressBar::enable_steady_tickspawns a thread whose first act is to draw a frame (TickerControl::runticks before its first wait), so a prefix set after that call races that tick. Both renderers had that ordering, so both could produce the frame; Linux and Windows happened to win the race and macOS did not. Reproduced deterministically by inserting a sleep into the pre-inversion path, which produced the exact failing value:Fixed in the sink rather than in the assertion: every bar is now fully styled and labelled before it is added to the
MultiProgressand, for spinners, before the ticker starts, so no frame can be drawn unlabelled.tests::a_spinner_is_labelled_before_its_first_tickwaits out several tick intervals and asserts every raw frame carries the prefix.Terminal output is unchanged — how that was verified
The previous revision compared old and new renderers frame-by-frame against a recording
indicatif::TermLike. Those renderers no longer exist, so before deleting them their output was captured and pinned as literals inevents.rs::rendering:✔/✘candid_compatskip, which usedfinish_with_messageand drew exactly one frame — soOutcome::Neutralmust callfinish_with_messagetoo, notset_message+finish, or it inserts an extra redrawFour things are normalized away, each because it is a property of the machine rather than of what was drawn: the blank padding row indicatif writes to fill the terminal line (a function of the frame it follows); the timer-driven animation glyph; SGR colour codes (a
TermLikedraw target is never stderr, so indicatif leaves the styled fields followingconsole's stdout-based detection — the frames carry colour whencargo testruns from a terminal and not when it is piped); and a spinner frame with no message yet, which is the animation thread getting a frame in before the operation has said anything. The last is what the macOS failure was made of; the underlying missing-prefix defect is fixed, not hidden.normalization_strips_the_colour_codes_a_terminal_would_addcovers the colour rule directly rather than leaving it assumed.Bar widths are deliberately not pinned once bytes have moved:
{wide_bar}takes whatever width the rest of the line leaves over, which includes a transfer rate whose text is as long as the machine happened to be fast. Those tests pin the glyph set and thedone/totalcounter instead.One intentional difference, called out rather than smoothed over: the byte-transfer bars in
canister snapshot upload/downloadare still drawn under--debug, matching today's behaviour, where the spinners are hidden. They are the only indication a long transfer is moving.Testability
Every converted operation is unit-tested by running it for real against a
RecordingSinkand asserting on the resultingVec<Event>— task order, exact messages, outcomes, step titles, step output. The three added in this pass:build.rs— a build's whole reported shape, a failing step's output and failure outcome, canister orderingsync.rs— the same three, driven through an injectedScriptRunnerthat reports lines instead of spawning a shellsnapshot_transfer.rs— a resumed upload reports the offset it recovered before anything else, so the bar opens where the last attempt stopped rather than at zeroicp's own suite gains one: a build step's output arrives through the writer and is retained for replay, with no terminal involved.Deliberately not in this PR
tracingcalls insideoperations/are stilltracingcalls.Event::Noticeexists and the sink routes it, so converting them needs no redesign. (INFO-leveltracingis product output in this CLI —logging.rsinstalls aUserLayerthat printsLevel::INFOto stderr unprefixed.)indicatifbars:commands/canister/migrate_id.rsandcommands/identity/link/web.rs. Neither ever went throughprogress.rs. Their look is genuinely different — no prefix, their own tick sets and colours,printlnthrough the bar,finish_and_clear— so converting them would mean either changing what the user sees or growing the event model to carry per-call-site styling for two call sites. Both are recorded in.claude/architecture.mdwith a grep to check the boundary holds.Stability
The event model is intentionally not semver-stable:
publish = false,0.xin lockstep withicp-cli, all enums#[non_exhaustive],TaskKindclosed rather than an open string. The event stream does not drive--json—--jsonkeeps meaning the command's final result, and no flag or feature is added that would change that.Checks
cargo build,cargo fmt --check,cargo clippy --workspace --all-targetsandcargo test --workspaceare clean, locally and through the validation pipeline (review, test, document, lint). The integration suites need the test network launcher fixture; theidentity_link_hsm*tests additionally need SoftHSM2 and thecanister_snapshot_*_resumetests needmitmproxy. One integration assertion moved with the code: thedebug!line that echoes step output now has the tracing targeticp::eventsrather thanicp::progress.Pipeline fixes folded in
Three findings the original change missed, fixed during validation:
goldens-ansi-sensitive— the goldens above were captured with colour off and would have failed whenever the test binary's stdout was a terminal.RecordingTermnow strips SGR codes in both its normalized and raw views, with a test that feeds escaped frames through and asserts both.architecture-grep-false-hits— the invariant check documented in.claude/architecture.mdmatchedevents::indicatif_reportertoo, so it listed 11 files while the prose claimed 3. Narrowed togrep -rl 'use indicatif'.sink-emit-repeated-lock— five arms ofIndicatifSink::emiteach repeated the same lock-and-look-up; collapsed into onewith_barhelper, so "events for an unknown task are ignored" lives in one place.Follow-up:
--debugoutput says which canister printed each lineA bug found after the inversion landed on this branch, fixed here rather than in a separate PR. Under
--debugthe bars are hidden, so thedebug!line the sink logs for each step-output event was the only record of a build's output — and it carried just the line, so canisters building in parallel interleaved into an unattributable stream. The bars have always shown the name in their prefix, so the two paths disagreed.BarStatenow keeps the prefix it gave the bar and the log line reuses it, so[backend] compilingreads the way the bar does. The prefix is kept at construction rather than read back off the bar. Byte tasks label their bars undecorated and keep doing so here; they report no step output today, so this settles the shape rather than changing anything. A line with no label, or one arriving for a task that has already finished, is still logged — bare — rather than dropped for want of a prefix.Verified on a real parallel build, because interleaving is the whole point and a single-canister check would pass while proving nothing: five canisters under
--debugproduced 20 output lines, every one attributed, none misattributed, with the canister changing between all 19 consecutive pairs. Sink-level tests cover the interleaved case, the unlabelled and unknown-task cases, and the byte-task shape; the interleaving test was mutation-checked against the baredebug!it replaced.Updating the integration assertions turned up a trap worth noting:
sync_testshad a negative assertion that no sync step ran ("DEBUG icp::events: syncing"must not appear), which the new prefix would have made vacuously true — green while testing nothing. It now matches"] syncing", a shape only the runtime log produces and which the--debugconfig dump does not.The pipeline also fixed a flaw in the new test helper: it captured
debug!lines through a thread-local subscriber, buttracingresolves and caches whether a callsite is enabled the first time any thread reaches it, so another test getting there first could cache "disabled" and leave the capture silent. It now installs one global subscriber per test binary and keys captured lines by thread id;.claude/testing.mdrecords that constraint.