feat: [IC-272] implement saving canister log records in sandbox safe …

…system state

rs/embedders/src/wasmtime_embedder/system_api.rs

@@ -577,10 +577,14 @@ pub(crate) fn syscalls(
     linker
         .func_wrap("ic0", "debug_print", {
             move |mut caller: Caller<'_, StoreData>, offset: u32, length: u32| {
+                let num_bytes = (match feature_flags.canister_logging {
+                    FlagStatus::Enabled => INSTRUCTIONS_PER_BYTE_CONVERSION_FACTOR,
+                    FlagStatus::Disabled => 1,
+                } * length) as u64;
                 charge_for_cpu_and_mem(
                     &mut caller,
                     overhead!(DEBUG_PRINT, metering_type),
-                    length as u64,
+                    num_bytes,
                 )?;
                 with_memory_and_system_api(&mut caller, |system_api, memory| {
                     if feature_flags.canister_logging == FlagStatus::Enabled {

rs/interfaces/src/execution_environment.rs

@@ -690,9 +690,6 @@ pub trait SystemApi {
         heap: &mut [u8],
     ) -> HypervisorResult<()>;
 
-    /// Logs the specified bytes on the heap as a string.
-    fn save_log_message(&self, src: u32, size: u32, heap: &[u8]);
-
     /// Outputs the specified bytes on the heap as a string on STDOUT.
     fn ic0_debug_print(&self, src: u32, size: u32, heap: &[u8]) -> HypervisorResult<()>;
 

rs/system_api/src/lib.rs

@@ -16,6 +16,7 @@ use ic_interfaces::execution_environment::{
     TrapCode::{self, CyclesAmountTooBigFor64Bit},
 };
 use ic_logger::{error, ReplicaLogger};
+use ic_management_canister_types::CanisterLogRecord;
 use ic_registry_subnet_type::SubnetType;
 use ic_replicated_state::{
     canister_state::WASM_PAGE_SIZE_IN_BYTES, memory_required_to_push_request, Memory, NumWasmPages,
@@ -1334,6 +1335,44 @@ impl SystemApiImpl {
     pub fn call_counters(&self) -> SystemApiCallCounters {
         self.call_counters.clone()
     }
+
+    /// Appends the specified bytes on the heap as a string to the canister's logs.
+    pub fn save_log_message(&mut self, src: u32, size: u32, heap: &[u8]) {
+        const MAX_LOG_MESSAGE_SIZE: u32 = 4 * 1024;
+        let size = size.min(MAX_LOG_MESSAGE_SIZE);
+        let msg = match valid_subslice("save_log_message", src, size, heap) {
+            Ok(bytes) => String::from_utf8_lossy(bytes).to_string(),
+            // Do not trap here!
+            // If the specified memory range is invalid, ignore it and log the error message.
+            Err(_) => "(save log message out of memory bounds)".to_string(),
+        };
+        match &self.api_type {
+            ApiType::Start { time }
+            | ApiType::Init { time, .. }
+            | ApiType::SystemTask { time, .. }
+            | ApiType::Update { time, .. }
+            | ApiType::Cleanup { time, .. }
+            | ApiType::NonReplicatedQuery { time, .. }
+            | ApiType::ReplicatedQuery { time, .. }
+            | ApiType::PreUpgrade { time, .. }
+            | ApiType::ReplyCallback { time, .. }
+            | ApiType::RejectCallback { time, .. }
+            | ApiType::InspectMessage { time, .. } => {
+                self.sandbox_safe_system_state.append_canister_log(
+                    time,
+                    format!(
+                        "[Canister {}] {}",
+                        self.sandbox_safe_system_state.canister_id, msg
+                    ),
+                )
+            }
+        }
+    }
+
+    /// Returns collected canister log records.
+    pub fn canister_log_records(&self) -> &Vec<CanisterLogRecord> {
+        self.sandbox_safe_system_state.canister_log_records()
+    }
 }
 
 impl SystemApi for SystemApiImpl {
@@ -2826,21 +2865,14 @@ impl SystemApi for SystemApiImpl {
         result
     }
 
-    fn save_log_message(&self, _src: u32, _size: u32, _heap: &[u8]) {
-        // TODO(IC-272): implement storing log message.
-    }
-
     fn ic0_debug_print(&self, src: u32, size: u32, heap: &[u8]) -> HypervisorResult<()> {
         const MAX_DEBUG_MESSAGE_SIZE: u32 = 32 * 1024;
         let size = size.min(MAX_DEBUG_MESSAGE_SIZE);
         let msg = match valid_subslice("ic0.debug_print", src, size, heap) {
             Ok(bytes) => String::from_utf8_lossy(bytes).to_string(),
-            Err(_) => {
-                // Do not trap here!
-                // debug.print should never fail, so if the specified memory range
-                // is invalid, we ignore it and print the error message
-                "(debug message out of memory bounds)".to_string()
-            }
+            // Do not trap here! `ic0_debug_print` should never fail!
+            // If the specified memory range is invalid, ignore it and print the error message.
+            Err(_) => "(debug message out of memory bounds)".to_string(),
         };
         match &self.api_type {
             ApiType::Start { time }

rs/system_api/src/sandbox_safe_system_state.rs

@@ -10,8 +10,9 @@ use ic_error_types::{ErrorCode, RejectCode, UserError};
 use ic_interfaces::execution_environment::{HypervisorError, HypervisorResult};
 use ic_logger::{info, ReplicaLogger};
 use ic_management_canister_types::{
-    CreateCanisterArgs, InstallChunkedCodeArgs, InstallCodeArgsV2, Method as Ic00Method, Payload,
-    ProvisionalCreateCanisterWithCyclesArgs, UninstallCodeArgs, UpdateSettingsArgs, IC_00,
+    CanisterLogRecord, CreateCanisterArgs, InstallChunkedCodeArgs, InstallCodeArgsV2,
+    Method as Ic00Method, Payload, ProvisionalCreateCanisterWithCyclesArgs, UninstallCodeArgs,
+    UpdateSettingsArgs, IC_00,
 };
 use ic_nns_constants::CYCLES_MINTING_CANISTER_ID;
 use ic_registry_subnet_type::SubnetType;
@@ -69,6 +70,7 @@ pub struct SystemStateChanges {
     request_slots_used: BTreeMap<CanisterId, usize>,
     requests: Vec<Request>,
     pub(super) new_global_timer: Option<CanisterTimer>,
+    canister_log_records: Vec<CanisterLogRecord>,
 }
 
 impl Default for SystemStateChanges {
@@ -83,6 +85,7 @@ impl Default for SystemStateChanges {
             request_slots_used: BTreeMap::new(),
             requests: vec![],
             new_global_timer: None,
+            canister_log_records: vec![],
         }
     }
 }
@@ -1185,6 +1188,22 @@ impl SandboxSafeSystemState {
             }
         }
     }
+
+    /// Appends a log record to the system state changes.
+    pub fn append_canister_log(&mut self, time: &Time, text: String) {
+        self.system_state_changes
+            .canister_log_records
+            .push(CanisterLogRecord {
+                idx: 27, // TODO(IC-272): populate idx value.
+                timestamp_nanos: time.as_nanos_since_unix_epoch(),
+                content: text.into_bytes(),
+            });
+    }
+
+    /// Returns collected canister log records.
+    pub fn canister_log_records(&self) -> &Vec<CanisterLogRecord> {
+        &self.system_state_changes.canister_log_records
+    }
 }
 
 /// Holds the metadata and the number of downstream requests. Requests created during the same

rs/system_api/tests/system_api.rs

@@ -1862,3 +1862,98 @@ fn test_ic0_cycles_burn() {
     // There are no more cycles that can be burned.
     assert_eq!(Cycles::new(0), Cycles::from(&heap));
 }
+
+#[test]
+fn test_save_log_message_adds_canister_log_records() {
+    let message = "Hello, world!";
+    // Create system api and remember the initial number of log records.
+    let mut api = get_system_api(
+        ApiTypeBuilder::build_update_api(),
+        &SystemStateBuilder::default().build(),
+        CyclesAccountManagerBuilder::new().build(),
+    );
+    let initial_number_of_records = api.canister_log_records().len();
+    // Save a log message.
+    let bytes = message.as_bytes();
+    api.save_log_message(0, bytes.len() as u32, bytes);
+    // Expect the number of log records to have increased by 1
+    // and the last record to contain the message.
+    let records = api.canister_log_records();
+    assert_eq!(records.len(), initial_number_of_records + 1);
+    assert_eq!(
+        String::from_utf8(records.last().unwrap().content.clone()).unwrap(),
+        format!("[Canister xbgkv-fyaaa-aaaaa-aaava-cai] {message}")
+    );
+}
+
+#[test]
+fn test_save_log_message_invalid_message_size() {
+    let message = "Hello, world!";
+    let bytes = message.as_bytes();
+    let invalid_size = (bytes.len() + 1) as u32;
+    // Create system api and remember the initial number of log records.
+    let mut api = get_system_api(
+        ApiTypeBuilder::build_update_api(),
+        &SystemStateBuilder::default().build(),
+        CyclesAccountManagerBuilder::new().build(),
+    );
+    let initial_number_of_records = api.canister_log_records().len();
+    // Save a log message.
+    api.save_log_message(0, invalid_size, bytes);
+    // Expect the number of log records to have increased by 1
+    // and the last record to contain the message.
+    let records = api.canister_log_records();
+    assert_eq!(records.len(), initial_number_of_records + 1);
+    assert_eq!(
+        String::from_utf8(records.last().unwrap().content.clone()).unwrap(),
+        "[Canister xbgkv-fyaaa-aaaaa-aaava-cai] (save log message out of memory bounds)"
+    );
+}
+
+#[test]
+fn test_save_log_message_invalid_message_offset() {
+    let message = "Hello, world!";
+    let invalid_src = 1;
+    // Create system api and remember the initial number of log records.
+    let mut api = get_system_api(
+        ApiTypeBuilder::build_update_api(),
+        &SystemStateBuilder::default().build(),
+        CyclesAccountManagerBuilder::new().build(),
+    );
+    let initial_number_of_records = api.canister_log_records().len();
+    // Save a log message.
+    let bytes = message.as_bytes();
+    api.save_log_message(invalid_src, bytes.len() as u32, bytes);
+    // Expect the number of log records to have increased by 1
+    // and the last record to contain the message.
+    let records = api.canister_log_records();
+    assert_eq!(records.len(), initial_number_of_records + 1);
+    assert_eq!(
+        String::from_utf8(records.last().unwrap().content.clone()).unwrap(),
+        "[Canister xbgkv-fyaaa-aaaaa-aaava-cai] (save log message out of memory bounds)"
+    );
+}
+
+#[test]
+fn test_save_log_message_trims_long_message() {
+    let long_message_size = 32 * 1024;
+    let max_allowed_message_size = 4 * 1024;
+    // Prefix size should cover canister id, the exact value is not important.
+    let prefix_size = 256;
+    assert!(prefix_size + max_allowed_message_size < long_message_size);
+    // Create system api and remember the initial number of log records.
+    let mut api = get_system_api(
+        ApiTypeBuilder::build_update_api(),
+        &SystemStateBuilder::default().build(),
+        CyclesAccountManagerBuilder::new().build(),
+    );
+    let initial_number_of_records = api.canister_log_records().len();
+    // Save a log message.
+    let bytes = vec![b'x'; long_message_size];
+    api.save_log_message(0, bytes.len() as u32, &bytes);
+    // Expect the number of log records to have increased by 1
+    // and the last record to contain trimmed message.
+    let records = api.canister_log_records();
+    assert_eq!(records.len(), initial_number_of_records + 1);
+    assert!(records.last().unwrap().content.len() < prefix_size + max_allowed_message_size);
+}

rs/types/management_canister_types/src/lib.rs

@@ -2347,7 +2347,7 @@ impl FetchCanisterLogsRequest {
 ///     content: blob;
 /// }
 /// ```
-#[derive(Default, Clone, CandidType, Deserialize, Debug, PartialEq, Eq)]
+#[derive(Default, Clone, CandidType, Serialize, Deserialize, Debug, PartialEq, Eq)]
 pub struct CanisterLogRecord {
     pub idx: u64,
     pub timestamp_nanos: u64,