Skip to content

fix: emit JSON from icp canister logs --json instead of human-readable text - #704

Merged
raymondk merged 3 commits into
mainfrom
fm/icp-logs-json
Aug 12, 2026
Merged

raymondk merged 3 commits into
mainfrom
fm/icp-logs-json

Conversation

@raymondk

Copy link
Copy Markdown
Collaborator

Intent

Fix an inverted condition that makes icp canister logs --json behave backwards.

The bug: in crates/icp-cli/src/commands/canister/logs.rs, function fetch_and_display_logs (the non-follow path), the two branches of if args.json { ... } else { ... } were swapped. The if args.json branch printed the human-readable formatted lines (.map(format_log).format("\n")) and the else branch serialized JsonListRecord with serde_json::to_writer. So --json emitted human text and the default emitted JSON. The follow path (follow_logs) already has the correct orientation - if args.json writes JSON, else prints format_log - and was used as the reference for intended behavior.

What was asked:

  1. Swap the two branch bodies in fetch_and_display_logs so --json produces the JSON output and the default produces the human-readable output.
  2. Check whether the JSON branch terminates its output with a newline the way the human branch does (human uses println!, JSON uses serde_json::to_writer on stdout()). If the fixed --json output would leave the shell prompt mid-line or be awkward to pipe, add the trailing newline. Do not restructure the output shape or field names beyond that.
  3. Confirm this is the only place the condition is inverted - grep the file and the command module for other args.json uses and verify each one against its intended orientation, and report whether others were found.

Acceptance criteria: --json prints machine-readable JSON and the default prints the existing human-readable formatted lines; follow mode (--follow) behavior unchanged; a regression test covers both orientations of the non-follow path, extending the existing crates/icp-cli/tests/canister_logs_tests.rs rather than creating a new test file and following the conventions there and in .claude/testing.md; cargo test, cargo fmt and cargo clippy clean.

Constraints: keep the change minimal and surgical - this is a bug fix, not a refactor of the logs command. Do not change the JSON schema (JsonListRecord / JsonFollowRecord field names or structure) or the human-readable format. Follow the repo conventions in .claude/CLAUDE.md, .claude/architecture.md and .claude/testing.md for paths (camino), error handling (Snafu) and tests. Regenerate CLI docs with ./scripts/generate-cli-docs.sh only if the change actually alters generated content.

Decisions and findings while doing the work:

  • Added the trailing newline deliberately: the fixed --json output would otherwise leave the shell prompt mid-line. Implemented as let mut out = stdout(); serde_json::to_writer(&mut out, ...)?; writeln!(out)?; with use std::io::{Write as _, stdout}. Note this intentionally differs from the surrounding house pattern - the other --json sites in the canister command module (list.rs, metadata.rs, snapshot/list.rs, snapshot/create.rs, snapshot/upload.rs, create.rs) all use bare serde_json::to_writer(stdout(), ..) with no trailing newline. Only the touched branch was changed, per the minimal-change constraint; the other sites were deliberately left alone rather than made consistent.
  • Audited every args.json / json_format use in crates/icp-cli/src/commands/canister/ (list.rs, metadata.rs, call.rs, create.rs x2, snapshot/{list,create,upload}.rs, settings/show.rs, and logs.rs:253 in the follow path). All were correctly oriented; logs.rs was the only inversion. The follow path was left untouched.
  • Regression test: added canister_logs_single_fetch_json_orientation to crates/icp-cli/tests/canister_logs_tests.rs, following the existing PocketIC / assert_cmd conventions in that file. It runs the real CLI against a live local network and asserts observable output: with --json, stdout parses as JSON with the log_records/timestamp/index/content shape and ends with a newline; without --json, stdout contains the human-readable "]: " line and does not contain log_records. Verified it fails against the unfixed source (reverted only the src file, kept the test) and passes with the fix.
  • Validation: cargo fmt --check, cargo clippy --all-targets, and all 5 canister_logs tests are clean. Full cargo test --workspace passes except canister_install_large_wasm_chunked, which fails on a missing tests/assets/large.wasm - a fixture generated by tests/assets/generate_large_wasm.sh that is absent in this fresh worktree. That failure is pre-existing and unrelated to this change.
  • ./scripts/generate-cli-docs.sh produced no diff (no help-text change), so no docs regeneration was committed.

What Changed

  • Swapped the two branch bodies of if args.json in fetch_and_display_logs (crates/icp-cli/src/commands/canister/logs.rs), so --json now serializes JsonListRecord and the default prints the format_log lines; the --follow path was already correct and is untouched.
  • Terminated the --json document with a trailing newline (writeln! on the same stdout handle) so the output does not leave the shell prompt mid-line, with a comment noting this deliberately differs from the other --json sites in the module.
  • Extended the existing canister_logs_single_fetch test to assert both orientations — the default output contains the ]: <message> lines and no log_records, and --json output ends with a newline and parses into a log_records array whose entries carry content, timestamp, and index — plus a CHANGELOG entry flagging that scripts relying on the inverted behavior must now pass --json.

Risk Assessment

✅ Low: A two-branch swap plus a trailing newline in a single non-follow output path, backed by a regression test that provably fails against the unfixed code in both orientations and a CHANGELOG entry documenting the script-visible behavior change; the JSON schema, human format, and follow path are untouched.

Testing

Ran the targeted logs integration tests and the logs module unit tests, all clean. Proved the added assertions are a true regression test by reverting only logs.rs to the base commit — the test fails there because the default invocation emits JSON — and passes once the fix is restored. Beyond the automated tests, I exercised the real icp binary against a live local PocketIC network with a deployed Motoko logger canister and captured before/after CLI transcripts: post-fix, --json emits newline-terminated machine-readable JSON that pipes cleanly into jq, while the default emits the human-readable [idx. timestamp]: content lines; pre-fix the same jq pipe failed and the JSON ran into the shell prompt mid-line. Follow mode was exercised in both orientations and is unchanged. I also independently audited all ten args.json/json_format sites in the canister command module and confirmed logs.rs:181 was the only inverted one, matching the author's reported finding. This is a CLI change with no rendered UI surface, so terminal transcripts (including an xxd byte-level check of the trailing newline) are the appropriate end-user evidence rather than screenshots. Cleaned up the throwaway project and its network launcher; the worktree is clean.

Evidence: Before/after CLI transcript: --json orientation fix

--- BEFORE (base 8fce05b, inverted) --- $ icp canister logs logger --environment random-environment {"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}$ icp canister logs logger --json --environment random-environment [0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister [1. 2026-08-12T05:17:04.076708234Z]: Second message $ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content" jq: parse error: Invalid numeric literal at line 1, column 18 --- AFTER (192f932, fixed) --- $ icp canister logs logger --environment random-environment # default: human-readable [0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister [1. 2026-08-12T05:17:04.076708234Z]: Second message $ icp canister logs logger --json --environment random-environment # --json: machine-readable {"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]} $ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content" Hello from the logger canister Second message $ icp canister logs logger --json --environment random-environment | xxd | tail -1 # last byte 0x0a = trailing newline 000000a0: 6f6e 6420 6d65 7373 6167 6522 7d5d 7d0a ond message"}]}. $ icp canister logs logger --since-index 1 --json --environment random-environment # --json honours filters {"log_records":[{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}

icp canister logs --json orientation: before vs after
=====================================================

--- BEFORE (base 8fce05b, inverted) ---
$ icp canister logs logger --environment random-environment
{"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}$ icp canister logs logger --json --environment random-environment
[0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister
[1. 2026-08-12T05:17:04.076708234Z]: Second message
$ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content"
jq: parse error: Invalid numeric literal at line 1, column 18
$ icp canister logs logger --json --environment random-environment | xxd | tail -1   # last byte is 0x0a (newline)
00000070: 6d65 7373 6167 650a                      message.


--- AFTER (192f932, fixed) ---
$ icp canister logs logger --environment random-environment          # default: human-readable
[0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister
[1. 2026-08-12T05:17:04.076708234Z]: Second message

$ icp canister logs logger --json --environment random-environment    # --json: machine-readable
{"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}
$ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content"
Hello from the logger canister
Second message

$ icp canister logs logger --json --environment random-environment | xxd | tail -1   # last byte 0x0a = trailing newline
000000a0: 6f6e 6420 6d65 7373 6167 6522 7d5d 7d0a  ond message"}]}.

$ icp canister logs logger --since-index 1 --json --environment random-environment    # --json honours filters
{"log_records":[{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}
Evidence: Post-fix CLI transcript (live local network)
$ icp canister logs logger --environment random-environment          # default: human-readable
[0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister
[1. 2026-08-12T05:17:04.076708234Z]: Second message

$ icp canister logs logger --json --environment random-environment    # --json: machine-readable
{"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}
$ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content"
Hello from the logger canister
Second message

$ icp canister logs logger --json --environment random-environment | xxd | tail -1   # last byte 0x0a = trailing newline
000000a0: 6f6e 6420 6d65 7373 6167 6522 7d5d 7d0a  ond message"}]}.

$ icp canister logs logger --since-index 1 --json --environment random-environment    # --json honours filters
{"log_records":[{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}
Evidence: Pre-fix CLI transcript (inverted behavior, base commit binary)
$ icp canister logs logger --environment random-environment
{"log_records":[{"timestamp":1786511823727360895,"index":0,"content":"Hello from the logger canister"},{"timestamp":1786511824076708234,"index":1,"content":"Second message"}]}$ icp canister logs logger --json --environment random-environment
[0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister
[1. 2026-08-12T05:17:04.076708234Z]: Second message
$ icp canister logs logger --json --environment random-environment | jq -r ".log_records[].content"
jq: parse error: Invalid numeric literal at line 1, column 18
$ icp canister logs logger --json --environment random-environment | xxd | tail -1   # last byte is 0x0a (newline)
00000070: 6d65 7373 6167 650a                      message.
Evidence: Follow mode unchanged (both orientations, live logs)

$ timeout 7 icp canister logs logger --follow --interval 1 --environment random-environment # follow, human-readable (unchanged) [0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister [1. 2026-08-12T05:17:04.076708234Z]: Second message [2. 2026-08-12T05:17:49.725315913Z]: 1 Tick [3. 2026-08-12T05:17:50.677686626Z]: 2 Tick [4. 2026-08-12T05:17:51.757141821Z]: 3 Tick [5. 2026-08-12T05:17:52.741121094Z]: 4 Tick [6. 2026-08-12T05:17:53.712770572Z]: 5 Tick $ timeout 7 icp canister logs logger --follow --json --interval 1 --environment random-environment | tail -c 400 # follow --json (unchanged) dex":5,"content":"4 Tick"}{"timestamp":1786511873712770572,"index":6,"content":"5 Tick"}{"timestamp":1786511877147032872,"index":7,"content":"1 Tock"}{"timestamp":1786511878112360361,"index":8,"content":"2 Tock"}

$ icp canister call ... logger log_repeated ("Tick")   # emits 5 logs, 1/second
()

$ timeout 7 icp canister logs logger --follow --interval 1 --environment random-environment    # follow, human-readable (unchanged)
[0. 2026-08-12T05:17:03.727360895Z]: Hello from the logger canister
[1. 2026-08-12T05:17:04.076708234Z]: Second message
[2. 2026-08-12T05:17:49.725315913Z]: 1 Tick
[3. 2026-08-12T05:17:50.677686626Z]: 2 Tick
[4. 2026-08-12T05:17:51.757141821Z]: 3 Tick
[5. 2026-08-12T05:17:52.741121094Z]: 4 Tick
[6. 2026-08-12T05:17:53.712770572Z]: 5 Tick

$ icp canister call ... logger log_repeated ("Tock")
()
$ timeout 7 icp canister logs logger --follow --json --interval 1 --environment random-environment | tail -c 400   # follow --json (unchanged)
dex":5,"content":"4 Tick"}{"timestamp":1786511873712770572,"index":6,"content":"5 Tick"}{"timestamp":1786511877147032872,"index":7,"content":"1 Tock"}{"timestamp":1786511878112360361,"index":8,"content":"2 Tock"}{"timestamp":1786511879160461332,"index":9,"content":"3 Tock"}{"timestamp":1786511880114864129,"index":10,"content":"4 Tock"}{"timestamp":1786511881180303692,"index":11,"content":"5 Tock"}
Evidence: Regression test fails against pre-fix source
$ git checkout 8fce05b -- crates/icp-cli/src/commands/canister/logs.rs
$ cargo test -p icp-cli --test canister_logs_tests -- canister_logs_single_fetch

thread 'canister_logs_single_fetch' panicked at crates/icp-cli/tests/canister_logs_tests.rs:90:10:
Unexpected stdout, failed var.contains(]: Test message 1)
├── var: {"log_records":[{"timestamp":1786511761844881385,"index":0,"content":"Test message 1"},{"timestamp":1786511762203854429,"index":1,"content":"Test message 2"}]}

command=`... icp canister logs logger --environment random-environment`
code=0

test result: FAILED. 0 passed; 1 failed; 0 ignored; 4 filtered out

--- after restoring the fix ---
test result: ok. 4 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 99.44s

Pipeline

Updates from git push no-mistakes

✅ **intent** - passed

✅ No issues found.

✅ **Rebase** - passed

✅ No issues found.

⚠️ **Review** - 1 info
  • ⚠️ CHANGELOG.md:8 - No # Unreleased CHANGELOG entry for this user-visible behavior change. CHANGELOG.md:8 (# Unreleased) is empty, and .github/workflows/release-pr.yml promotes exactly that section into the release notes, so this fix would ship undocumented. It matters more than a typical fix note because the default (no-flag) output changes from JSON to human-readable text: any script that worked around the inverted condition by omitting --json and parsing stdout as JSON breaks silently on upgrade. Comparable user-facing fixes in v1.3.0 (e.g. the icp network start error-reporting fix) do carry entries. Suggested line: "fix: icp canister logs --json now emits JSON and the default emits human-readable lines; the two were swapped. Scripts that parsed the default output as JSON must pass --json."
  • ℹ️ crates/icp-cli/src/commands/canister/logs.rs:256 - Pre-existing, and explicitly out of the stated minimal scope, but now asymmetric with the fixed branch: in the follow path each record is written with bare serde_json::to_writer(stdout(), ..) and no newline. Rust's Stdout is a LineWriter, so with --follow --json nothing reaches the terminal/pipe until ~1KB of buffer fills or the process exits — the live-tail property that --follow exists for is lost, and records arrive concatenated ({..}{..}) rather than newline-delimited (NDJSON), which a consumer of a streaming log feed would expect. The one-line writeln!(out) pattern just adopted at logs.rs:197 would fix both. Flagging for follow-up triage only; not a blocker, since the intent states follow-mode behavior is unchanged.
  • ℹ️ crates/icp-cli/tests/canister_logs_tests.rs:97 - The new test re-runs the entire expensive fixture of canister_logs_single_fetch (PocketIC network start + ping_until_healthy + a Motoko deploy) to assert output shape, adding a fifth full network/compile cycle to this file. The existing canister_logs_single_fetch at line 15 already deploys the same logger and writes log records, so both orientations could be asserted there (it already covers the human-readable orientation), keeping regression coverage identical at roughly half the wall-clock cost. Deliberate author choice per the stated intent, so raising it rather than changing it.

🔧 Fix: add changelog entry, fold logs JSON test into existing test
1 info still open:

  • ℹ️ crates/icp-cli/src/commands/canister/logs.rs:181 - Independently confirmed the intent's audit claim (item 3): every other args.json / json_format site in crates/icp-cli/src/commands/canister/ is correctly oriented — list.rs:26, metadata.rs:50, call.rs:244, create.rs:305 and :394, snapshot/list.rs:58, snapshot/create.rs:86, snapshot/upload.rs:219, settings/show.rs:53, and logs.rs:255 (follow path). Also checked status.rs:239, :262 and :292, which the author's audit list omitted; those use match args.options.json_format { true =&gt; serde_json::to_string(..), false =&gt; build_output(..) } and are correct. logs.rs:181 was the only inversion. No action needed.
✅ **Test** - passed

✅ No issues found.

  • cargo test -p icp-cli --test canister_logs_tests -- --test-threads=1 (4 passed, 1 pre-existing #[ignore])
  • cargo test -p icp-cli --bin icp commands::canister::logs (22 unit tests, incl. format_log/format_content/build_filter)
  • Regression proof: git checkout 8fce05b -- crates/icp-cli/src/commands/canister/logs.rs then cargo test -p icp-cli --test canister_logs_tests -- canister_logs_single_fetch — FAILED with var: {&#34;log_records&#34;:[...]} on the default (non---json) invocation; restored the fix and it passes
  • Manual end-to-end: deployed the logger Motoko canister to a live local network (icp network start random-network, icp deploy logger), emitted logs via icp canister call logger log, then captured real stdout for icp canister logs logger vs icp canister logs logger --json
  • Pipe check: icp canister logs logger --json ... | jq -r &#39;.log_records[].content&#39; (succeeds post-fix; jq: parse error pre-fix)
  • Trailing-newline check: icp canister logs logger --json ... | xxd | tail -1 confirms final byte 0x0a
  • Filter interaction: icp canister logs logger --since-index 1 --json ... returns only the filtered record in JSON
  • Follow mode unchanged: timeout 7 icp canister logs logger --follow --interval 1 ... and timeout 7 icp canister logs logger --follow --json --interval 1 ... against live log_repeated output
  • Inversion audit: grep -rn &#39;\.json\b|json_format&#39; crates/icp-cli/src/commands/canister/ and inspected each branch body in list.rs, metadata.rs, call.rs, create.rs (x2), snapshot/{list,create,upload}.rs, settings/show.rs, status.rs, and logs.rs:255 (follow path)
✅ **Document** - passed

✅ No issues found.

✅ **Lint** - passed

✅ No issues found.

✅ **Push** - passed

✅ No issues found.

raymondk and others added 3 commits August 12, 2026 04:48
The two branches of `if args.json` in `fetch_and_display_logs` were
swapped: `--json` printed the human-readable `format_log` lines while
the default printed the `JsonListRecord` serialization. Swap them back
so the non-follow path matches the follow path's orientation.

Also terminate the JSON output with a newline so it does not leave the
shell prompt mid-line.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@raymondk
raymondk requested a review from a team as a code owner August 12, 2026 05:27
Copilot AI balanced review requested due to automatic review settings August 12, 2026 05:27

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Fixes non-following canister logs output so --json emits JSON and the default remains human-readable.

Changes:

  • Corrected output branch orientation and added a trailing JSON newline.
  • Added regression coverage for both formats.
  • Documented the behavior correction.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated no comments.

File Description
crates/icp-cli/src/commands/canister/logs.rs Corrects output formatting.
crates/icp-cli/tests/canister_logs_tests.rs Tests both output orientations.
CHANGELOG.md Documents the user-visible fix.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

@raymondk
raymondk merged commit bccb7df into main Aug 12, 2026
100 checks passed
@raymondk
raymondk deleted the fm/icp-logs-json branch August 12, 2026 06:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants