Skip to content

feat: Support follow mode for 'dfx canister logs'. #4215

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Apr 21, 2025
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,11 @@

# UNRELEASED

### feat: Support 'follow' mode for 'dfx canister logs'
Support `follow` mode for `dfx canister logs`
- `--follow` to fetch logs continuously until interrupted with `Ctrl+C`
- `--interval` to specify the interval in seconds between log fetches

### feat: Improve 'dfx canister logs' with several options

Improve `dfx canister logs` with several options
Expand Down
10 changes: 9 additions & 1 deletion docs/cli-reference/dfx-canister.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -639,9 +639,11 @@ You can specify the following options for the `dfx canister logs` command.

| Option | Description |
|-----------------------------|-----------------------------------------------------------------------------------------------------|
| `--tail <tail>` | Specifies to show the last number of the logs. |
| `--follow` | Specifies to fetch logs continuously until interrupted with `Ctrl+C`. |
| `--interval <interval>` | Specifies the interval in seconds between log fetches when following logs. Defaults to 2 seconds. |
| `--since <since>` | Specifies to show the logs newer than a relative duration, with the valid units `s`, `m`, `h`, `d`. |
| `--since-time <since-time>` | Specifies to show the logs newer than a specific timestamp. Required either `nanoseconds` since Unix epoch or `RFC3339` format (e.g. `2021-05-06T19:17:10.000000002Z`). |
| `--tail <tail>` | Specifies to show the last number of the logs. |

### Examples

Expand Down Expand Up @@ -698,6 +700,12 @@ The command displays output similar to the following:
[45. 2021-05-06T19:17:15.000000002Z]: (bytes) 0xc0ffee
```

To fetch logs continuously, you can run the following command:

``` bash
dfx canister logs hello_world --follow
```

## dfx canister metadata

Use the `dfx canister metadata` command to display metadata stored in a canister's Wasm module.
Expand Down
213 changes: 147 additions & 66 deletions src/dfx/src/commands/canister/logs.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,8 @@ use crate::util::clap::parsers::{duration_parser, timestamp_parser};
use candid::Principal;
use clap::Parser;
use dfx_core::identity::CallSender;
use ic_utils::interfaces::management_canister::FetchCanisterLogsResponse;
use std::time::{SystemTime, UNIX_EPOCH};
use ic_utils::interfaces::management_canister::{CanisterLogRecord, FetchCanisterLogsResponse};
use std::time::{Duration, SystemTime, UNIX_EPOCH};
use time::format_description::well_known::Rfc3339;
use time::OffsetDateTime;

Expand All @@ -22,21 +22,40 @@ pub struct LogsOpts {
tail: Option<u64>,

/// Specifies to show the logs newer than a relative duration, with the valid units 's', 'm', 'h', 'd'.
#[arg(long, conflicts_with("tail"), conflicts_with("since_time"), value_parser = duration_parser)]
#[arg(long, conflicts_with("tail"), conflicts_with("since_time"), conflicts_with("follow"), value_parser = duration_parser)]
since: Option<u64>,

/// Specifies to show the logs newer than a specific timestamp.
/// Required either nanoseconds since Unix epoch or RFC3339 format (e.g. '2021-05-06T19:17:10.000000002Z').
#[arg(long, conflicts_with("tail"), conflicts_with("since"), value_parser = timestamp_parser)]
#[arg(long, conflicts_with("tail"), conflicts_with("since"), conflicts_with("follow"), value_parser = timestamp_parser)]
since_time: Option<u64>,

/// Specifies to fetch logs continuously until interrupted with Ctrl+C.
#[arg(
long,
conflicts_with("tail"),
conflicts_with("since"),
conflicts_with("since_time")
)]
follow: bool,

/// Specifies the interval in seconds between log fetches when following logs. Defaults to 2 seconds.
#[arg(long, requires("follow"))]
interval: Option<u64>,
}

fn format_bytes(bytes: &[u8]) -> String {
format!("(bytes) 0x{}", hex::encode(bytes))
struct FilterOpts {
tail: Option<u64>,
since: Option<u64>,
since_time: Option<u64>,
last_idx: Option<u64>,
}

fn format_canister_logs(logs: FetchCanisterLogsResponse, opts: &LogsOpts) -> Vec<String> {
let filtered_logs = if let Some(number) = opts.tail {
fn filter_canister_logs<'a>(
logs: &'a FetchCanisterLogsResponse,
opts: FilterOpts,
) -> &'a [CanisterLogRecord] {
if let Some(number) = opts.tail {
&logs.canister_log_records[logs
.canister_log_records
.len()
Expand All @@ -57,16 +76,22 @@ fn format_canister_logs(logs: FetchCanisterLogsResponse, opts: &LogsOpts) -> Vec
.canister_log_records
.partition_point(|r| r.timestamp_nanos <= since_time);
&logs.canister_log_records[index..]
} else if let Some(last_idx) = opts.last_idx {
let index = logs
.canister_log_records
.partition_point(|r| r.idx <= last_idx);
&logs.canister_log_records[index..]
} else {
&logs.canister_log_records
};

if filtered_logs.is_empty() {
return vec!["No logs".to_string()];
}
}

fn format_bytes(bytes: &[u8]) -> String {
format!("(bytes) 0x{}", hex::encode(bytes))
}

filtered_logs
.iter()
fn format_canister_logs(logs: &[CanisterLogRecord]) -> Vec<String> {
logs.iter()
.map(|r| {
let time = OffsetDateTime::from_unix_timestamp_nanos(r.timestamp_nanos as i128)
.expect("Invalid canister log record timestamp");
Expand All @@ -91,10 +116,58 @@ fn format_canister_logs(logs: FetchCanisterLogsResponse, opts: &LogsOpts) -> Vec
.collect()
}

pub async fn exec(env: &dyn Environment, opts: LogsOpts, call_sender: &CallSender) -> DfxResult {
let callee_canister = opts.canister.as_str();
let canister_id_store = env.get_canister_id_store()?;

let canister_id = Principal::from_text(callee_canister)
.or_else(|_| canister_id_store.get(callee_canister))?;

fetch_root_key_if_needed(env).await?;

if opts.follow {
let interval = opts.interval.unwrap_or(2);
let mut last_idx = 0u64;

loop {
let logs = canister::get_canister_logs(env, canister_id, call_sender).await?;
let filter_opts = FilterOpts {
tail: None,
since: None,
since_time: None,
last_idx: Some(last_idx),
};
let filtered_logs = filter_canister_logs(&logs, filter_opts);

if !filtered_logs.is_empty() {
println!("{}", format_canister_logs(filtered_logs).join("\n"));
last_idx = filtered_logs.last().unwrap().idx;
}

tokio::select! {
_ = tokio::time::sleep(Duration::from_secs(interval)) => continue,
_ = tokio::signal::ctrl_c() => break,
}
}
} else {
let logs = canister::get_canister_logs(env, canister_id, call_sender).await?;

let filter_opts = FilterOpts {
tail: opts.tail,
since: opts.since,
since_time: opts.since_time,
last_idx: None,
};
let filtered_logs = filter_canister_logs(&logs, filter_opts);

println!("{}", format_canister_logs(filtered_logs).join("\n"));
}

Ok(())
}

#[test]
fn test_format_canister_logs() {
use ic_utils::interfaces::management_canister::CanisterLogRecord;

let logs = FetchCanisterLogsResponse {
canister_log_records: vec![
CanisterLogRecord {
Expand Down Expand Up @@ -130,16 +203,17 @@ fn test_format_canister_logs() {
],
};

let filtered_logs = filter_canister_logs(
&logs,
FilterOpts {
tail: None,
since: None,
since_time: None,
last_idx: None,
},
);
assert_eq!(
format_canister_logs(
logs.clone(),
&LogsOpts {
canister: "2vxsx-fae".to_string(),
tail: None,
since: None,
since_time: None,
}
),
format_canister_logs(filtered_logs),
vec![
"[42. 2021-05-06T19:17:10.000000001Z]: Some text message".to_string(),
"[43. 2021-05-06T19:17:10.000000002Z]: (bytes) 0xc0ffee".to_string(),
Expand All @@ -151,16 +225,17 @@ fn test_format_canister_logs() {
);

// Test tail
let filtered_logs = filter_canister_logs(
&logs,
FilterOpts {
tail: Some(4),
since: None,
since_time: None,
last_idx: None,
},
);
assert_eq!(
format_canister_logs(
logs.clone(),
&LogsOpts {
canister: "2vxsx-fae".to_string(),
tail: Some(4),
since: None,
since_time: None,
}
),
format_canister_logs(filtered_logs),
vec![
"[44. 2021-05-06T19:17:10.000000003Z]: (bytes) 0xc0ffee".to_string(),
"[45. 2021-05-06T19:17:15.000000001Z]: Five seconds later".to_string(),
Expand All @@ -175,16 +250,17 @@ fn test_format_canister_logs() {
.unwrap()
.as_secs()
- 1620328631; // 1 second after the first log with idx 42.
let filtered_logs = filter_canister_logs(
&logs,
FilterOpts {
tail: None,
since: Some(duration_seconds),
since_time: None,
last_idx: None,
},
);
assert_eq!(
format_canister_logs(
logs.clone(),
&LogsOpts {
canister: "2vxsx-fae".to_string(),
tail: None,
since: Some(duration_seconds),
since_time: None,
}
),
format_canister_logs(filtered_logs),
vec![
"[45. 2021-05-06T19:17:15.000000001Z]: Five seconds later".to_string(),
"[46. 2021-05-06T19:17:15.000000002Z]: (bytes) 0xc0ffee".to_string(),
Expand All @@ -193,35 +269,40 @@ fn test_format_canister_logs() {
);

// Test since_time
let filtered_logs = filter_canister_logs(
&logs,
FilterOpts {
tail: None,
since: None,
since_time: Some(1_620_328_635_000_000_000),
last_idx: None,
},
);
assert_eq!(
format_canister_logs(
logs,
&LogsOpts {
canister: "2vxsx-fae".to_string(),
tail: None,
since: None,
since_time: Some(1_620_328_635_000_000_000),
}
),
format_canister_logs(filtered_logs),
vec![
"[45. 2021-05-06T19:17:15.000000001Z]: Five seconds later".to_string(),
"[46. 2021-05-06T19:17:15.000000002Z]: (bytes) 0xc0ffee".to_string(),
"[47. 2021-05-06T19:17:15.000000003Z]: (bytes) 0xc0ffee".to_string(),
]
);
}

pub async fn exec(env: &dyn Environment, opts: LogsOpts, call_sender: &CallSender) -> DfxResult {
let callee_canister = opts.canister.as_str();
let canister_id_store = env.get_canister_id_store()?;

let canister_id = Principal::from_text(callee_canister)
.or_else(|_| canister_id_store.get(callee_canister))?;

fetch_root_key_if_needed(env).await?;

let logs = canister::get_canister_logs(env, canister_id, call_sender).await?;
println!("{}", format_canister_logs(logs, &opts).join("\n"));

Ok(())
// Test last index
let filtered_logs = filter_canister_logs(
&logs,
FilterOpts {
tail: None,
since: None,
since_time: None,
last_idx: Some(44),
},
);
assert_eq!(
format_canister_logs(filtered_logs),
vec![
"[45. 2021-05-06T19:17:15.000000001Z]: Five seconds later".to_string(),
"[46. 2021-05-06T19:17:15.000000002Z]: (bytes) 0xc0ffee".to_string(),
"[47. 2021-05-06T19:17:15.000000003Z]: (bytes) 0xc0ffee".to_string(),
]
);
}