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",
@@ -94,6 +97,7 @@ rust_ic_test(
         ":btc_kyt_lib",
         "//:pocket-ic-server",
         "//packages/pocket-ic",
+        "//rs/rust_canisters/http_types",
         "//rs/test_utilities/load_wasm",
         "//rs/types/base_types",
         "//rs/types/types",

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::WARN;
 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!(WARN, "{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!(WARN, "{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 = WARN, capacity = 1000);
+
+// Low-priority info messages.
+declare_log_buffer!(name = DEBUG, capacity = 1000);
+
+#[derive(Clone, Debug, Deserialize, Serialize)]
+pub enum Priority {
+    Warn,
+    Debug,
+}
+
+#[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,37 @@ 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, DEBUG, WARN};
 use state::{get_config, set_config, Config, FetchGuardError, HttpGetTxError};
 
+#[derive(Default)]
+struct Stats {
+    https_outcall_status: BTreeMap<(String, u16), u64>,
+    http_response_size: BTreeMap<u32, 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 +56,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 +91,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()
@@ -126,9 +146,145 @@ fn post_upgrade(arg: KytArg) {
 
 #[ic_cdk::query(hidden = true)]
 fn http_request(req: http::HttpRequest) -> http::HttpResponse {
+    if ic_cdk::api::data_certificate().is_none() {
+        ic_cdk::trap("update call rejected");
+    }
+
+    #[cfg(target_arch = "wasm32")]
+    fn heap_memory_size_bytes() -> usize {
+        const WASM_PAGE_SIZE_BYTES: usize = 65536;
+        core::arch::wasm32::memory_size(0) * WASM_PAGE_SIZE_BYTES
+    }
+
+    #[cfg(not(any(target_arch = "wasm32")))]
+    fn heap_memory_size_bytes() -> usize {
+        0
+    }
+
     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(
+                "heap_memory_bytes",
+                heap_memory_size_bytes() as f64,
+                "Size of the heap memory allocated by this canister.",
+            )
+            .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 ((provider, status), count) in stats.https_outcall_status.iter() {
+                counter = counter
+                    .value(
+                        &[
+                            ("provider", provider.as_str()),
+                            ("status", status.to_string().as_str()),
+                        ],
+                        *count as f64,
+                    )
+                    .unwrap();
+            }
+            let mut counter = writer
+                .counter_vec(
+                    "btc_kyt_http_response_size",
+                    "The byte sizes of http outcall responses.",
+                )
+                .unwrap();
+            for (size, count) in stats.http_response_size.iter() {
+                counter = counter
+                    .value(&[("size", size.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(&WARN) {
+            if entry.timestamp >= max_skip_timestamp {
+                entries.entries.push(LogEntry {
+                    timestamp: entry.timestamp,
+                    counter: entry.counter,
+                    priority: Priority::Warn,
+                    file: entry.file.to_string(),
+                    line: entry.line,
+                    message: entry.message,
+                });
+            }
+        }
+        for entry in export_logs(&DEBUG) {
+            if entry.timestamp >= max_skip_timestamp {
+                entries.entries.push(LogEntry {
+                    timestamp: entry.timestamp,
+                    counter: entry.counter,
+                    priority: Priority::Debug,
+                    file: entry.file.to_string(),
+                    line: entry.line,
+                    message: entry.message,
+                });
+            }
+        }
+        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 +338,18 @@ 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| {
+                    let mut stat = s.borrow_mut();
+                    *stat
+                        .https_outcall_status
+                        .entry((provider.name(), response.status.0.to_u16().unwrap()))
+                        .or_default() += 1;
+                    // Calculate size bucket as a series of power of 2s.
+                    // Note that the max is bounded by `max_response_bytes`, which fits `u32`.
+                    let size = 2u32.pow((response.body.len() as f64).log2().floor() as u32);
+                    *stat.http_response_size.entry(size).or_default() += 1;
+                });
+
                 // Ensure response is 200 before decoding
                 if response.status != 200u32 {
                     // All non-200 status are treated as transient errors
@@ -224,8 +392,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!(
+                    DEBUG,
+                    "The http_request resulted into error. RejectionCode: {r:?}, Error: {m}, Request: {request:?}"
+                );
                 Err(HttpGetTxError::Rejected {
                     code: r,
                     message: m,

rs/bitcoin/kyt/src/providers.rs

@@ -57,6 +57,14 @@ impl Provider {
         &self.btc_network
     }
 
+    pub fn name(&self) -> String {
+        match self.btc_network {
+            BtcNetwork::Mainnet => self.provider_id.to_string(),
+            BtcNetwork::Testnet => "Testnet".to_string(),
+            BtcNetwork::Regtest { .. } => "Regtest".to_string(),
+        }
+    }
+
     // Return the next provider by cycling through all available providers.
     pub fn next(&self) -> Self {
         let btc_network = &self.btc_network;