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

* Decouple log filtering and formatting.

* Support follow mode in 'dfx canister logs'.

* Update document and changelog.

* Revert to the previous behaviour.

Author: vincent-dfinity

CHANGELOG.md

@@ -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

docs/cli-reference/dfx-canister.mdx

@@ -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
 
@@ -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.

src/dfx/src/commands/canister/logs.rs

@@ -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;
 
@@ -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()
@@ -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");
@@ -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 {
@@ -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(),
@@ -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(),
@@ -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(),
@@ -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(),
+        ]
+    );
 }