Merge branch 'main' into spofford/complete

Author: raymondk

CHANGELOG.md

@@ -8,6 +8,7 @@ bump. Currently experimental: project bundling, project dependencies
 # Unreleased
 
 * feat: `icp completions <SHELL>` 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.
 
 # v1.3.0
 

crates/icp-cli/src/commands/canister/logs.rs

@@ -1,4 +1,4 @@
-use std::io::stdout;
+use std::io::{ErrorKind, Write as _, stdout};
 
 use anyhow::{Context as _, anyhow};
 use candid::Principal;
@@ -179,17 +179,9 @@ async fn fetch_and_display_logs(
         .context("Failed to fetch canister logs")?;
 
     if args.json {
-        println!(
-            "{}",
-            result
-                .canister_log_records
-                .iter()
-                .map(format_log)
-                .format("\n")
-        );
-    } else {
+        let mut out = stdout();
         serde_json::to_writer(
-            stdout(),
+            &mut out,
             &JsonListRecord {
                 log_records: result
                     .canister_log_records
@@ -202,6 +194,18 @@ async fn fetch_and_display_logs(
                     .collect(),
             },
         )?;
+        // Terminate the document with a newline: it is the entirety of stdout, so without
+        // it the shell prompt lands mid-line. Covered by `canister_logs_single_fetch`.
+        writeln!(out)?;
+    } else {
+        println!(
+            "{}",
+            result
+                .canister_log_records
+                .iter()
+                .map(format_log)
+                .format("\n")
+        );
     }
 
     Ok(())
@@ -219,7 +223,7 @@ async fn follow_logs(
     let mut last_idx: Option<u64> = None;
     let interval = std::time::Duration::from_secs(interval_seconds);
 
-    loop {
+    'follow: loop {
         let filter = match last_idx {
             Some(idx) => Some(CanisterLogFilter::ByIdx {
                 start: idx + 1, // Start from the next log index after the last one we displayed
@@ -250,17 +254,26 @@ async fn follow_logs(
 
         if !new_logs.is_empty() {
             for log in &new_logs {
-                if args.json {
-                    serde_json::to_writer(
-                        stdout(),
-                        &JsonFollowRecord {
-                            timestamp: log.timestamp_nanos,
-                            index: log.idx,
-                            content: String::from_utf8_lossy(&log.content).into_owned(),
-                        },
-                    )?;
+                let line = if args.json {
+                    serde_json::to_string(&JsonFollowRecord {
+                        timestamp: log.timestamp_nanos,
+                        index: log.idx,
+                        content: String::from_utf8_lossy(&log.content).into_owned(),
+                    })?
                 } else {
-                    println!("{}", format_log(log));
+                    format_log(log)
+                };
+                // Under `--json` this makes the output newline-delimited: the newline both
+                // separates records for incremental consumers and, because Rust's stdout is a
+                // `LineWriter` regardless of whether it is a terminal, flushes the record so
+                // that `--follow` actually streams. Covered by `canister_logs_follow_mode_json`.
+                match writeln!(stdout().lock(), "{line}") {
+                    Ok(()) => {}
+                    // The consumer closed the pipe (`... --follow --json | head -1`). That is
+                    // an ordinary way to stop a tail, so stop quietly rather than reporting a
+                    // broken pipe. Covered by `canister_logs_follow_broken_pipe`.
+                    Err(e) if e.kind() == ErrorKind::BrokenPipe => break 'follow,
+                    Err(e) => return Err(e.into()),
                 }
             }
             // Update last_idx to the highest idx we've displayed

crates/icp-cli/tests/canister_logs_tests.rs

@@ -5,6 +5,8 @@ use {
     indoc::formatdoc,
     predicates::prelude::PredicateBooleanExt,
     predicates::str::contains,
+    std::io::{BufRead as _, BufReader},
+    std::process::Stdio,
     std::time::Duration,
 };
 
@@ -74,7 +76,8 @@ async fn canister_logs_single_fetch() {
         .assert()
         .success();
 
-    // Fetch logs
+    // Fetch logs: the default emits the human-readable "[idx. timestamp]: content" lines,
+    // not JSON. (Regression: this orientation was once swapped with `--json`.)
     ctx.icp()
         .current_dir(&project_dir)
         .args([
@@ -86,10 +89,51 @@ async fn canister_logs_single_fetch() {
         ])
         .assert()
         .success()
-        .stdout(contains("Test message 1"))
-        .stdout(contains("Test message 2"));
+        .stdout(contains("]: Test message 1"))
+        .stdout(contains("]: Test message 2"))
+        .stdout(contains("log_records").not());
+
+    // With --json: parseable JSON in the JsonListRecord shape, terminated by a newline.
+    let json_stdout = ctx
+        .icp()
+        .current_dir(&project_dir)
+        .args([
+            "canister",
+            "logs",
+            "logger",
+            "--json",
+            "--environment",
+            "random-environment",
+        ])
+        .assert()
+        .success()
+        .get_output()
+        .stdout
+        .clone();
+    let json_stdout = String::from_utf8(json_stdout).expect("stdout is not valid UTF-8");
+    assert!(
+        json_stdout.ends_with('\n'),
+        "--json output should end with a newline, got {json_stdout:?}"
+    );
+    let parsed: serde_json::Value =
+        serde_json::from_str(json_stdout.trim()).expect("--json output should be valid JSON");
+    let records = parsed["log_records"]
+        .as_array()
+        .expect("--json output should contain a log_records array");
+    for message in ["Test message 1", "Test message 2"] {
+        let record = records
+            .iter()
+            .find(|r| r["content"].as_str() == Some(message))
+            .unwrap_or_else(|| panic!("--json output should contain {message:?}"));
+        assert!(record["timestamp"].is_u64());
+        assert!(record["index"].is_u64());
+    }
 }
 
+/// Every `--follow` behaviour, in one network start and one `moc` deploy: each phase would
+/// otherwise pay for its own, which dominates the wall clock. Covers (1) polling for logs
+/// that do not exist yet, (2) `--json` streaming newline-delimited records as they arrive,
+/// and (3) a consumer that stops reading ending the command quietly.
 #[cfg(unix)] // moc
 #[tokio::test]
 async fn canister_logs_follow_mode() {
@@ -126,27 +170,23 @@ async fn canister_logs_follow_mode() {
         .assert()
         .success();
 
-    // Trigger repeated logging (will log 5 times over 5 seconds)
-    ctx.icp()
-        .current_dir(&project_dir)
-        .args([
-            "canister",
-            "call",
-            "--environment",
-            "random-environment",
-            "logger",
-            "log_repeated",
-            "(\"Repeated\")",
-        ])
-        .assert()
-        .success();
-
-    // Start following logs with a timeout of 7 seconds (enough to see several logs)
-    // The logs are not present yet, so if e.g. "5 Repeated" is present in stdout after the timeout, then we correctly polled for new logs
-    ctx.icp()
-        .current_dir(&project_dir)
-        .timeout(Duration::from_secs(7))
-        .args([
+    let call = |method: &str, message: &str| {
+        ctx.icp()
+            .current_dir(&project_dir)
+            .args([
+                "canister",
+                "call",
+                "--environment",
+                "random-environment",
+                "logger",
+                method,
+                &format!("(\"{message}\")"),
+            ])
+            .assert()
+            .success();
+    };
+    let follow_args = |json: bool| {
+        let mut args = vec![
             "canister",
             "logs",
             "logger",
@@ -155,14 +195,103 @@ async fn canister_logs_follow_mode() {
             "1",
             "--environment",
             "random-environment",
-        ])
+        ];
+        if json {
+            args.push("--json");
+        }
+        args
+    };
+
+    // Phase 1: the human-readable output polls for new logs. `log_repeated` returns
+    // immediately and logs 5 times over 5 seconds from a recurring timer, so none of these
+    // records exist when the follow starts — seeing "5 Repeated" within the 7s window means
+    // we really polled rather than replaying the 1-hour lookback.
+    call("log_repeated", "Repeated");
+    ctx.icp()
+        .current_dir(&project_dir)
+        .timeout(Duration::from_secs(7))
+        .args(follow_args(false))
         .assert()
         .failure() // Will timeout/be interrupted
         .stdout(contains("1 Repeated"))
         .stdout(contains("2 Repeated"))
         .stdout(contains("3 Repeated"))
         .stdout(contains("4 Repeated"))
         .stdout(contains("5 Repeated"));
+
+    // Phase 2: `--json` streams newline-delimited records. Same fresh-logs setup, and
+    // because the timeout SIGKILLs the process rather than letting it exit, nothing buffered
+    // in stdout is flushed on the way out: any output we observe must have been flushed as
+    // the records arrived. Parsing each line on its own also pins the delimiting, since
+    // `serde_json::from_str` rejects the trailing content of a concatenated `{...}{...}`.
+    call("log_repeated", "Streamed");
+    let stdout = ctx
+        .icp()
+        .current_dir(&project_dir)
+        .timeout(Duration::from_secs(7))
+        .args(follow_args(true))
+        .assert()
+        .failure() // Will timeout/be interrupted
+        .get_output()
+        .stdout
+        .clone();
+    let stdout = String::from_utf8(stdout).expect("stdout is not valid UTF-8");
+    let mut contents = Vec::new();
+    for line in stdout.lines() {
+        let record: serde_json::Value = serde_json::from_str(line)
+            .unwrap_or_else(|e| panic!("--follow --json line {line:?} is not valid JSON: {e}"));
+        assert!(record["timestamp"].is_u64());
+        assert!(record["index"].is_u64());
+        contents.push(
+            record["content"]
+                .as_str()
+                .expect("--follow --json record should contain a content string")
+                .to_string(),
+        );
+    }
+    for i in 1..=5 {
+        let message = format!("{i} Streamed");
+        assert!(
+            contents.iter().any(|c| c.contains(&message)),
+            "--follow --json output should contain {message:?}, got {contents:?}"
+        );
+    }
+
+    // Phase 3: a consumer that stops reading — `icp canister logs --follow | head -1` — must
+    // not make the command report a broken pipe. `--json` writes far more often now that it
+    // streams, so it reaches the closed pipe first, but both modes share the same write.
+    for json in [true, false] {
+        let mut child = ctx
+            .icp_std()
+            .current_dir(&project_dir)
+            .args(follow_args(json))
+            .stdout(Stdio::piped())
+            .spawn()
+            .expect("failed to spawn icp canister logs --follow");
+
+        // Read one record, then close the read end of the pipe, exactly as `head -1` does.
+        let mut reader = BufReader::new(child.stdout.take().expect("stdout is piped"));
+        let mut line = String::new();
+        reader
+            .read_line(&mut line)
+            .expect("failed to read the first record");
+        assert!(
+            !line.is_empty(),
+            "expected a first record before the pipe closed (json: {json})"
+        );
+        drop(reader);
+
+        // Produce another record so the next poll must write to the now-closed pipe. The
+        // earlier phases left plenty for the first poll to emit, but this makes the write
+        // independent of how much the lookback happens to return.
+        call("log", &format!("After close {json}"));
+
+        let status = child.wait().expect("failed to wait for icp canister logs");
+        assert!(
+            status.success(),
+            "a closed stdout pipe should end `--follow` quietly (json: {json}), got {status}"
+        );
+    }
 }
 
 #[cfg(unix)] // moc

crates/icp-cli/tests/common/context.rs

@@ -99,7 +99,14 @@ impl TestContext {
     }
 
     pub(crate) fn icp(&self) -> Command {
-        let mut cmd = Command::new(icp_bin_path());
+        Command::from_std(self.icp_std())
+    }
+
+    /// The same isolated `icp` invocation as [`TestContext::icp`], as a raw
+    /// [`std::process::Command`] so a caller can wire up stdio itself — e.g. to spawn a
+    /// long-running command and close its stdout pipe part-way through.
+    pub(crate) fn icp_std(&self) -> std::process::Command {
+        let mut cmd = std::process::Command::new(icp_bin_path());
 
         // Isolate the command
         cmd.current_dir(self.home_path());

docs-site/package-lock.json

@@ -2,9 +2,12 @@
   "$comment": "Before first release: Empty array redirects to /main/. After releases: Add versions here (newest first). Only 'version' is required; 'latest: true' marks the current release.",
   "versions": [
     {
-      "version": "1.2",
+      "version": "1.3",
       "latest": true
     },
+    {
+      "version": "1.2"
+    },
     {
       "version": "1.1"
     },

docs-site/versions.json

@@ -1 +1 @@
-15.0.0-2026-07-31-04-23
+15.0.0-2026-08-06-04-21