chore: [EXC-2089] Add logs in system API to track whether bitcoin methods are called on the management canister (#6088)

Calling the bitcoin API via the management canister is
[deprecated](https://internetcomputer.org/docs/references/ic-interface-spec#ic-bitcoin-api)
since a while ago and developers are expected to interact with the
relevant bitcoin canister (mainnet or testnet) directly.

This PR adds a log that would catch any cases where this is still
happening in preparation of fully removing this code from the replica.
Adding a log was preferred over adding some metric as we don't have
access to a `MetricsRegistry` in the system API and propagating that
would be a bunch more work. Instead, adding a log is fairly easier/less
invasive (some info is still propagated to help diagnose but it's quite
limited in scope).

Author: dsarlis

rs/embedders/src/wasmtime_embedder/system_api/routing.rs

@@ -4,6 +4,7 @@ use std::str::FromStr;
 use ic_base_types::{CanisterId, PrincipalId, SubnetId};
 use ic_btc_interface::NetworkInRequest as BitcoinNetwork;
 use ic_error_types::UserError;
+use ic_logger::{info, ReplicaLogger};
 use ic_management_canister_types_private::{
     BitcoinGetBalanceArgs, BitcoinGetBlockHeadersArgs, BitcoinGetCurrentFeePercentilesArgs,
     BitcoinGetUtxosArgs, BitcoinSendTransactionArgs, CanisterIdRecord, CanisterInfoRequest,
@@ -57,6 +58,8 @@ pub(super) fn resolve_destination(
     method_name: &str,
     payload: &[u8],
     own_subnet: SubnetId,
+    caller: CanisterId,
+    logger: &ReplicaLogger,
 ) -> Result<PrincipalId, ResolveDestinationError> {
     // Figure out the destination subnet based on the method and the payload.
     let method = Ic00Method::from_str(method_name);
@@ -131,6 +134,9 @@ pub(super) fn resolve_destination(
                 args.network,
                 network_topology,
                 own_subnet,
+                caller,
+                method_name,
+                logger,
             ))
         }
         Ok(Ic00Method::BitcoinGetUtxos) => {
@@ -139,6 +145,9 @@ pub(super) fn resolve_destination(
                 args.network,
                 network_topology,
                 own_subnet,
+                caller,
+                method_name,
+                logger,
             ))
         }
         Ok(Ic00Method::BitcoinGetBlockHeaders) => {
@@ -147,6 +156,9 @@ pub(super) fn resolve_destination(
                 args.network,
                 network_topology,
                 own_subnet,
+                caller,
+                method_name,
+                logger,
             ))
         }
         Ok(Ic00Method::BitcoinSendTransaction) => {
@@ -156,6 +168,9 @@ pub(super) fn resolve_destination(
                 args.network,
                 network_topology,
                 own_subnet,
+                caller,
+                method_name,
+                logger,
             ))
         }
         Ok(Ic00Method::BitcoinGetCurrentFeePercentiles) => {
@@ -164,6 +179,9 @@ pub(super) fn resolve_destination(
                 args.network,
                 network_topology,
                 own_subnet,
+                caller,
+                method_name,
+                logger,
             ))
         }
         Ok(Ic00Method::NodeMetricsHistory) => {
@@ -431,7 +449,17 @@ fn route_bitcoin_message(
     network: BitcoinNetwork,
     network_topology: &NetworkTopology,
     own_subnet: SubnetId,
+    caller: CanisterId,
+    method_name: &str,
+    logger: &ReplicaLogger,
 ) -> PrincipalId {
+    info!(
+        logger,
+        "Canister {} called Bitcoin method {} with network: {:?} directly on the management canister",
+        caller,
+        method_name,
+        network
+    );
     match network {
         // Route to the bitcoin canister if it exists, otherwise route to own subnet.
         // NOTE: Local deployments can run regtest mode for testing, and that routes to the
@@ -455,6 +483,7 @@ mod tests {
     use assert_matches::assert_matches;
     use candid::Encode;
     use ic_base_types::RegistryVersion;
+    use ic_logger::no_op_logger;
     use ic_management_canister_types_private::{
         DerivationPath, EcdsaCurve, EcdsaKeyId, SchnorrAlgorithm, SchnorrKeyId, SignWithECDSAArgs,
         VetKdCurve, VetKdKeyId,
@@ -612,6 +641,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -623,6 +653,8 @@ mod tests {
                     &Ic00Method::ReshareChainKey.to_string(),
                     &reshare_chain_key_request(key_id.clone(), subnet_test_id(1)),
                     subnet_test_id(2),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap(),
                 PrincipalId::new_subnet_test_id(1)
@@ -632,6 +664,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key_key_not_held_error() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -643,6 +676,8 @@ mod tests {
                     &Ic00Method::ReshareChainKey.to_string(),
                     &reshare_chain_key_request(key_id.clone(), subnet_test_id(2)),
                     subnet_test_id(2),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap_err(),
                 ResolveDestinationError::ChainKeyError(err) => assert_eq!(
@@ -659,6 +694,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key_unknown_subnet_error() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -670,6 +706,8 @@ mod tests {
                     &Ic00Method::ReshareChainKey.to_string(),
                     &reshare_chain_key_request(key_id.clone(), subnet_test_id(3)),
                     subnet_test_id(2),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap_err(),
                 ResolveDestinationError::ChainKeyError(err) => assert_eq!(
@@ -686,6 +724,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key_wrong_subnet_error() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -698,6 +737,8 @@ mod tests {
                         // Subnet 2 doesn't have the requested key.
                         &reshare_chain_key_request(key_id.clone(), subnet_test_id(2)),
                         subnet_test_id(2),
+                        canister_test_id(1),
+                        &logger,
                     )
                     .unwrap_err(),
                     ResolveDestinationError::ChainKeyError(err) => assert_eq!(
@@ -714,6 +755,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key_subnet_not_found_error() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -726,6 +768,8 @@ mod tests {
                     // Subnet 3 doesn't exist
                     &reshare_chain_key_request(key_id.clone(), subnet_test_id(3)),
                     subnet_test_id(2),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap_err(),
                 ResolveDestinationError::ChainKeyError(err) => assert_eq!(
@@ -742,6 +786,7 @@ mod tests {
 
     #[test]
     fn resolve_chain_key_request() {
+        let logger = no_op_logger();
         for (network_topology, method, payload) in [
             (
                 network_with_ecdsa_subnets(),
@@ -765,6 +810,8 @@ mod tests {
                     &method.to_string(),
                     &payload,
                     subnet_test_id(1),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap(),
                 PrincipalId::new_subnet_test_id(0)
@@ -774,6 +821,7 @@ mod tests {
 
     #[test]
     fn resolve_chain_key_request_error() {
+        let logger = no_op_logger();
         for (method, payload, master_key_id) in [
             (
                 Ic00Method::SignWithECDSA,
@@ -796,6 +844,8 @@ mod tests {
                 &method.to_string(),
                 &payload,
                 subnet_test_id(1),
+                canister_test_id(1),
+                &logger,
             )
             .unwrap_err(),
             ResolveDestinationError::ChainKeyError(err) => assert_eq!(
@@ -811,6 +861,7 @@ mod tests {
 
     #[test]
     fn resolve_chain_key_public_key_works_with_disabled_keys() {
+        let logger = no_op_logger();
         for (network_topology, method, payload) in [
             (
                 network_with_ecdsa_subnets(),
@@ -834,6 +885,8 @@ mod tests {
                     &method.to_string(),
                     &payload,
                     subnet_test_id(1),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap(),
                 PrincipalId::new_subnet_test_id(0)
@@ -843,6 +896,7 @@ mod tests {
 
     #[test]
     fn resolve_reshare_chain_key_works_with_disabled_keys() {
+        let logger = no_op_logger();
         for (network_topology, key_id) in [
             (network_with_ecdsa_subnets(), ecdsa_master_key_id(1)),
             (network_with_schnorr_subnets(), schnorr_master_key_id(1)),
@@ -854,6 +908,8 @@ mod tests {
                     &Ic00Method::ReshareChainKey.to_string(),
                     &reshare_chain_key_request(key_id, subnet_test_id(0)),
                     subnet_test_id(1),
+                    canister_test_id(1),
+                    &logger,
                 )
                 .unwrap(),
                 PrincipalId::new_subnet_test_id(0)

rs/embedders/src/wasmtime_embedder/system_api/sandbox_safe_system_state.rs

@@ -400,6 +400,8 @@ impl SystemStateModifications {
                             msg.method_name.as_str(),
                             msg.method_payload.as_slice(),
                             own_subnet_id,
+                            system_state.canister_id,
+                            logger,
                         )
                         .map(CanisterId::unchecked_from_principal)
                         {