From f74f81d400b358e1209a62a790d87789ac4a407b Mon Sep 17 00:00:00 2001 From: Maksym Arutyunyan Date: Mon, 19 Feb 2024 18:37:13 +0000 Subject: [PATCH] feat: [IC-272] implement saving canister log records in sandbox safe system state --- .../src/wasmtime_embedder/system_api.rs | 6 +- rs/interfaces/src/execution_environment.rs | 3 - rs/system_api/src/lib.rs | 52 ++++++++-- .../src/sandbox_safe_system_state.rs | 23 ++++- rs/system_api/tests/system_api.rs | 95 +++++++++++++++++++ rs/types/management_canister_types/src/lib.rs | 2 +- 6 files changed, 164 insertions(+), 17 deletions(-) diff --git a/rs/embedders/src/wasmtime_embedder/system_api.rs b/rs/embedders/src/wasmtime_embedder/system_api.rs index b4e129b0522..566ca7d2495 100644 --- a/rs/embedders/src/wasmtime_embedder/system_api.rs +++ b/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 { diff --git a/rs/interfaces/src/execution_environment.rs b/rs/interfaces/src/execution_environment.rs index ef4ea7a0ad6..98543ea6008 100644 --- a/rs/interfaces/src/execution_environment.rs +++ b/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<()>; diff --git a/rs/system_api/src/lib.rs b/rs/system_api/src/lib.rs index 70500fed4da..62be47cf317 100644 --- a/rs/system_api/src/lib.rs +++ b/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 { + 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 } diff --git a/rs/system_api/src/sandbox_safe_system_state.rs b/rs/system_api/src/sandbox_safe_system_state.rs index f5d1132248a..c6b355f475e 100644 --- a/rs/system_api/src/sandbox_safe_system_state.rs +++ b/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, requests: Vec, pub(super) new_global_timer: Option, + canister_log_records: Vec, } 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 { + &self.system_state_changes.canister_log_records + } } /// Holds the metadata and the number of downstream requests. Requests created during the same diff --git a/rs/system_api/tests/system_api.rs b/rs/system_api/tests/system_api.rs index 7a5858a87fa..71c22fb74e5 100644 --- a/rs/system_api/tests/system_api.rs +++ b/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); +} diff --git a/rs/types/management_canister_types/src/lib.rs b/rs/types/management_canister_types/src/lib.rs index a5042fddcc5..d65111dafe6 100644 --- a/rs/types/management_canister_types/src/lib.rs +++ b/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,