chore(ckbtc): add metrics and logging to the KYT canister

rs/bitcoin/kyt/BUILD.bazel

@@ -67,8 +67,11 @@ rust_canister(
         "@crate_index//:futures",
         "@crate_index//:hex",
         "@crate_index//:ic-btc-interface",
+        "@crate_index//:ic-canister-log",
         "@crate_index//:ic-cdk",
+        "@crate_index//:ic-metrics-encoder",
         "@crate_index//:ic-stable-structures",
+        "@crate_index//:num-traits",
         "@crate_index//:serde",
         "@crate_index//:serde_json",
         "@crate_index//:time",

rs/bitcoin/kyt/Cargo.toml

@@ -19,9 +19,12 @@ ciborium = { workspace = true }
 futures = { workspace = true }
 hex = { workspace = true }
 ic-btc-interface = { workspace = true }
+ic-canister-log = { path = "../../rust_canisters/canister_log" }
 ic-canisters-http-types = { path = "../../rust_canisters/http_types" }
 ic-cdk = { workspace = true }
+ic-metrics-encoder = "1.1"
 ic-stable-structures = { workspace = true }
+num-traits = { workspace = true }
 serde = { workspace = true }
 serde_json = {workspace = true }
 time = { workspace = true }

rs/bitcoin/kyt/src/fetch.rs

@@ -1,3 +1,4 @@
+use crate::logs::P0;
 use crate::state::{
     FetchGuardError, FetchTxStatus, FetchTxStatusError, FetchedTx, HttpGetTxError,
     TransactionKytData,
@@ -11,6 +12,7 @@ use ic_btc_kyt::{
     CheckTransactionRetriable, CheckTransactionStatus, INITIAL_MAX_RESPONSE_BYTES,
     RETRY_MAX_RESPONSE_BYTES,
 };
+use ic_canister_log::log;
 use std::convert::Infallible;
 
 #[cfg(test)]
@@ -216,14 +218,13 @@ pub trait FetchEnv {
                             state::set_fetched_address(txid, index, address.clone());
                         } else {
                             // This error shouldn't happen unless blockdata is corrupted.
-                            // TODO(XC-205): log this error
-                            return CheckTransactionIrrecoverableError::InvalidTransaction(
-                                format!(
-                                    "Tx {} vout {} has no address, but is vin {} of tx {}",
-                                    input.txid, input.vout, index, txid
-                                ),
-                            )
-                            .into();
+                            let msg = format!(
+                                "Tx {} vout {} has no address, but is vin {} of tx {}",
+                                input.txid, input.vout, index, txid
+                            );
+                            log!(P0, "{msg}");
+                            return CheckTransactionIrrecoverableError::InvalidTransaction(msg)
+                                .into();
                         }
                     }
                     Pending => {}
@@ -259,13 +260,13 @@ pub trait FetchEnv {
                         state::set_fetched_address(txid, index, address.clone());
                     } else {
                         // This error shouldn't happen unless blockdata is corrupted.
-                        // TODO(XC-205): log this error
+                        let msg = format!(
+                            "Tx {} vout {} has no address, but is vin {} of tx {}",
+                            input_txid, vout, index, txid
+                        );
+                        log!(P0, "{msg}");
                         error = Some(
-                            CheckTransactionIrrecoverableError::InvalidTransaction(format!(
-                                "Tx {} vout {} has no address, but is vin {} of tx {}",
-                                input_txid, vout, index, txid
-                            ))
-                            .into(),
+                            CheckTransactionIrrecoverableError::InvalidTransaction(msg).into(),
                         );
                     }
                 }

rs/bitcoin/kyt/src/logs.rs

@@ -0,0 +1,29 @@
+use ic_canister_log::declare_log_buffer;
+use serde::{Deserialize, Serialize};
+
+// High-priority messages.
+declare_log_buffer!(name = P0, capacity = 1000);
+
+// Low-priority info messages.
+declare_log_buffer!(name = P1, capacity = 1000);
+
+#[derive(Clone, Debug, Deserialize, Serialize)]
+pub enum Priority {
+    P0,
+    P1,
+}
+
+#[derive(Clone, Debug, Deserialize, Serialize)]
+pub struct LogEntry {
+    pub timestamp: u64,
+    pub priority: Priority,
+    pub file: String,
+    pub line: u32,
+    pub message: String,
+    pub counter: u64,
+}
+
+#[derive(Clone, Debug, Default, Deserialize, Serialize)]
+pub struct Log {
+    pub entries: Vec<LogEntry>,
+}

rs/bitcoin/kyt/src/main.rs

@@ -6,19 +6,36 @@ use ic_btc_kyt::{
     CheckTransactionRetriable, CheckTransactionStatus, KytArg, KytMode,
     CHECK_TRANSACTION_CYCLES_REQUIRED, CHECK_TRANSACTION_CYCLES_SERVICE_FEE,
 };
+use ic_canister_log::{export as export_logs, log};
 use ic_canisters_http_types as http;
 use ic_cdk::api::call::RejectionCode;
 use ic_cdk::api::management_canister::http_request::{HttpResponse, TransformArgs};
+use num_traits::cast::ToPrimitive;
+use std::cell::RefCell;
+use std::collections::BTreeMap;
 use std::str::FromStr;
 
 mod dashboard;
 mod fetch;
+mod logs;
 mod providers;
 mod state;
 
 use fetch::{FetchEnv, FetchResult, TryFetchResult};
+use logs::{Log, LogEntry, Priority, P0, P1};
 use state::{get_config, set_config, Config, FetchGuardError, HttpGetTxError};
 
+#[derive(Default)]
+struct Stats {
+    https_outcall_status: BTreeMap<u16, u64>,
+    check_transaction_count: u64,
+    check_address_count: u64,
+}
+
+thread_local! {
+    static STATS : RefCell<Stats> = RefCell::default();
+}
+
 pub fn is_response_too_large(code: &RejectionCode, message: &str) -> bool {
     code == &RejectionCode::SysFatal
         && (message.contains("size limit") || message.contains("length limit"))
@@ -38,6 +55,7 @@ fn check_address(args: CheckAddressArgs) -> CheckAddressResponse {
             ic_cdk::trap(&format!("Not a bitcoin {} address: {}", btc_network, err))
         });
 
+    STATS.with(|s| s.borrow_mut().check_transaction_count += 1);
     match config.kyt_mode() {
         KytMode::AcceptAll => CheckAddressResponse::Passed,
         KytMode::RejectAll => CheckAddressResponse::Failed,
@@ -72,6 +90,7 @@ async fn check_transaction(args: CheckTransactionArgs) -> CheckTransactionRespon
     ic_cdk::api::call::msg_cycles_accept128(CHECK_TRANSACTION_CYCLES_SERVICE_FEE);
     match Txid::try_from(args.txid.as_ref()) {
         Ok(txid) => {
+            STATS.with(|s| s.borrow_mut().check_transaction_count += 1);
             if ic_cdk::api::call::msg_cycles_available128()
                 .checked_add(CHECK_TRANSACTION_CYCLES_SERVICE_FEE)
                 .unwrap()
@@ -127,8 +146,103 @@ fn post_upgrade(arg: KytArg) {
 #[ic_cdk::query(hidden = true)]
 fn http_request(req: http::HttpRequest) -> http::HttpResponse {
     if req.path() == "/metrics" {
-        // TODO(XC-205): Add metrics
-        unimplemented!()
+        let mut writer =
+            ic_metrics_encoder::MetricsEncoder::new(vec![], ic_cdk::api::time() as i64 / 1_000_000);
+
+        let cycle_balance = ic_cdk::api::canister_balance128() as f64;
+
+        writer
+            .gauge_vec("cycle_balance", "The canister cycle balance.")
+            .unwrap()
+            .value(&[("canister", "btc-kyt")], cycle_balance)
+            .unwrap();
+
+        writer
+            .encode_gauge(
+                "stable_memory_bytes",
+                ic_cdk::api::stable::stable_size() as f64 * 65536.0,
+                "Size of the stable memory allocated by this canister.",
+            )
+            .unwrap();
+
+        STATS.with(|s| {
+            let stats = s.borrow();
+            let mut counter = writer
+                .counter_vec(
+                    "btc_kyt_http_calls_total",
+                    "The number of http outcalls made since the last canister upgrade.",
+                )
+                .unwrap();
+            for (status, count) in stats.https_outcall_status.iter() {
+                counter = counter
+                    .value(&[("status", status.to_string().as_str())], *count as f64)
+                    .unwrap();
+            }
+            writer
+                .counter_vec(
+                    "ckbtc_kyt_requests_total",
+                    "The number of KYT requests received since the last canister upgrade.",
+                )
+                .unwrap()
+                .value(
+                    &[("type", "check_transaction")],
+                    stats.check_transaction_count as f64,
+                )
+                .unwrap()
+                .value(
+                    &[("type", "check_address")],
+                    stats.check_address_count as f64,
+                )
+                .unwrap();
+        });
+
+        http::HttpResponseBuilder::ok()
+            .header("Content-Type", "text/plain; version=0.0.4")
+            .with_body_and_content_length(writer.into_inner())
+            .build()
+    } else if req.path() == "/logs" {
+        use serde_json;
+
+        let max_skip_timestamp = match req.raw_query_param("time") {
+            Some(arg) => match u64::from_str(arg) {
+                Ok(value) => value,
+                Err(_) => {
+                    return http::HttpResponseBuilder::bad_request()
+                        .with_body_and_content_length("failed to parse the 'time' parameter")
+                        .build()
+                }
+            },
+            None => 0,
+        };
+
+        let mut entries: Log = Default::default();
+        for entry in export_logs(&P0) {
+            entries.entries.push(LogEntry {
+                timestamp: entry.timestamp,
+                counter: entry.counter,
+                priority: Priority::P0,
+                file: entry.file.to_string(),
+                line: entry.line,
+                message: entry.message,
+            });
+        }
+        for entry in export_logs(&P1) {
+            entries.entries.push(LogEntry {
+                timestamp: entry.timestamp,
+                counter: entry.counter,
+                priority: Priority::P1,
+                file: entry.file.to_string(),
+                line: entry.line,
+                message: entry.message,
+            });
+        }
+        entries
+            .entries
+            .retain(|entry| entry.timestamp >= max_skip_timestamp);
+        http::HttpResponseBuilder::ok()
+            .header("Content-Type", "application/json; charset=utf-8")
+            .with_body_and_content_length(serde_json::to_string(&entries).unwrap_or_default())
+            .build()
     } else if req.path() == "/dashboard" {
         use askama::Template;
         let page_index = match req.raw_query_param("page") {
@@ -182,6 +296,13 @@ impl FetchEnv for KytCanisterEnv {
         let cycles = get_tx_cycle_cost(max_response_bytes);
         match http_request(request.clone(), cycles).await {
             Ok((response,)) => {
+                STATS.with(|s| {
+                    *s.borrow_mut()
+                        .https_outcall_status
+                        .entry(response.status.0.to_u16().unwrap())
+                        .or_default() += 1
+                });
+
                 // Ensure response is 200 before decoding
                 if response.status != 200u32 {
                     // All non-200 status are treated as transient errors
@@ -224,8 +345,10 @@ impl FetchEnv for KytCanisterEnv {
             }
             Err((r, m)) if is_response_too_large(&r, &m) => Err(HttpGetTxError::ResponseTooLarge),
             Err((r, m)) => {
-                // TODO(XC-158): maybe try other providers and also log the error.
-                println!("The http_request resulted into error. RejectionCode: {r:?}, Error: {m}");
+                log!(
+                    P1,
+                    "The http_request resulted into error. RejectionCode: {r:?}, Error: {m}"
+                );
                 Err(HttpGetTxError::Rejected {
                     code: r,
                     message: m,