diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 79201397db..fa1542f92c 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -4,7 +4,6 @@ use crate::{ instruction_recorder::InstructionRecorder, log_collector::LogCollector, }; -use log::*; use solana_sdk::{ account::{AccountSharedData, ReadableAccount}, compute_budget::ComputeBudget, @@ -23,18 +22,12 @@ use solana_sdk::{ use std::{cell::RefCell, rc::Rc, sync::Arc}; /// Compute meter -pub trait ComputeMeter { - /// Consume compute units - fn consume(&mut self, amount: u64) -> Result<(), InstructionError>; - /// Get the number of remaining compute units - fn get_remaining(&self) -> u64; -} - -pub struct ThisComputeMeter { +pub struct ComputeMeter { remaining: u64, } -impl ComputeMeter for ThisComputeMeter { - fn consume(&mut self, amount: u64) -> Result<(), InstructionError> { +impl ComputeMeter { + /// Consume compute units + pub fn consume(&mut self, amount: u64) -> Result<(), InstructionError> { let exceeded = self.remaining < amount; self.remaining = self.remaining.saturating_sub(amount); if exceeded { @@ -42,77 +35,16 @@ impl ComputeMeter for ThisComputeMeter { } Ok(()) } - fn get_remaining(&self) -> u64 { + /// Get the number of remaining compute units + pub fn get_remaining(&self) -> u64 { self.remaining } -} -impl ThisComputeMeter { + /// Construct a new one with the given remaining units pub fn new_ref(remaining: u64) -> Rc> { Rc::new(RefCell::new(Self { remaining })) } } -/// Log messages -pub trait Logger { - fn log_enabled(&self) -> bool; - - /// Log a message. - /// - /// Unless explicitly stated, log messages are not considered stable and may change in the - /// future as necessary - fn log(&self, message: &str); -} - -pub struct ThisLogger { - log_collector: Option>, -} -impl Logger for ThisLogger { - fn log_enabled(&self) -> bool { - log_enabled!(log::Level::Info) || self.log_collector.is_some() - } - fn log(&self, message: &str) { - debug!("{}", message); - if let Some(log_collector) = &self.log_collector { - log_collector.log(message); - } - } -} -impl ThisLogger { - pub fn new_ref(log_collector: Option>) -> Rc> { - Rc::new(RefCell::new(Self { log_collector })) - } -} - -/// Convenience macro to log a message with an `Rc>` -#[macro_export] -macro_rules! ic_logger_msg { - ($logger:expr, $message:expr) => { - if let Ok(logger) = $logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log($message); - } - } - }; - ($logger:expr, $fmt:expr, $($arg:tt)*) => { - if let Ok(logger) = $logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!($fmt, $($arg)*)); - } - } - }; -} - -/// Convenience macro to log a message with an `InvokeContext` -#[macro_export] -macro_rules! ic_msg { - ($invoke_context:expr, $message:expr) => { - $crate::ic_logger_msg!($invoke_context.get_logger(), $message) - }; - ($invoke_context:expr, $fmt:expr, $($arg:tt)*) => { - $crate::ic_logger_msg!($invoke_context.get_logger(), $fmt, $($arg)*) - }; -} - pub struct InvokeContextStackFrame<'a> { pub number_of_program_accounts: usize, pub keyed_accounts: Vec>, @@ -147,10 +79,10 @@ pub struct ThisInvokeContext<'a> { accounts: &'a [(Pubkey, Rc>)], programs: &'a [(Pubkey, ProcessInstructionWithContext)], sysvars: &'a [(Pubkey, Vec)], - logger: Rc>, + log_collector: Option>>, compute_budget: ComputeBudget, current_compute_budget: ComputeBudget, - compute_meter: Rc>, + compute_meter: Rc>, executors: Rc>, instruction_recorders: Option<&'a [InstructionRecorder]>, feature_set: Arc, @@ -166,9 +98,9 @@ impl<'a> ThisInvokeContext<'a> { accounts: &'a [(Pubkey, Rc>)], programs: &'a [(Pubkey, ProcessInstructionWithContext)], sysvars: &'a [(Pubkey, Vec)], - log_collector: Option>, + log_collector: Option>>, compute_budget: ComputeBudget, - compute_meter: Rc>, + compute_meter: Rc>, executors: Rc>, instruction_recorders: Option<&'a [InstructionRecorder]>, feature_set: Arc, @@ -183,7 +115,7 @@ impl<'a> ThisInvokeContext<'a> { accounts, programs, sysvars, - logger: ThisLogger::new_ref(log_collector), + log_collector, current_compute_budget: compute_budget, compute_budget, compute_meter, @@ -210,7 +142,7 @@ impl<'a> ThisInvokeContext<'a> { sysvars, None, ComputeBudget::default(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), Rc::new(RefCell::new(Executors::default())), None, feature_set, @@ -272,10 +204,10 @@ pub trait InvokeContext { fn get_keyed_accounts(&self) -> Result<&[KeyedAccount], InstructionError>; /// Get a list of built-in programs fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)]; - /// Get this invocation's logger - fn get_logger(&self) -> Rc>; - /// Get this invocation's compute meter - fn get_compute_meter(&self) -> Rc>; + /// Get this invocation's LogCollector + fn get_log_collector(&self) -> Option>>; + /// Get this invocation's ComputeMeter + fn get_compute_meter(&self) -> Rc>; /// Loaders may need to do work in order to execute a program. Cache /// the work that can be re-used across executions fn add_executor(&self, pubkey: &Pubkey, executor: Arc); @@ -349,8 +281,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { self.current_compute_budget = compute_budget; if !self.feature_set.is_active(&tx_wide_compute_cap::id()) { - self.compute_meter = - ThisComputeMeter::new_ref(self.current_compute_budget.max_units); + self.compute_meter = ComputeMeter::new_ref(self.current_compute_budget.max_units); } self.pre_accounts = Vec::with_capacity(instruction.accounts.len()); @@ -464,7 +395,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { ) .map_err(|err| { ic_logger_msg!( - self.logger, + self.log_collector, "failed to verify account {}: {}", pre_account.key(), err @@ -500,7 +431,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { .and_then(|frame| frame.program_id()) .ok_or(InstructionError::CallDepth)?; let rent = &self.rent; - let logger = &self.logger; + let log_collector = &self.log_collector; let accounts = &self.accounts; let pre_accounts = &mut self.pre_accounts; let timings = &mut self.timings; @@ -535,7 +466,12 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { do_support_realloc, ) .map_err(|err| { - ic_logger_msg!(logger, "failed to verify account {}: {}", key, err); + ic_logger_msg!( + log_collector, + "failed to verify account {}: {}", + key, + err + ); err })?; pre_sum = pre_sum @@ -587,10 +523,10 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)] { self.programs } - fn get_logger(&self) -> Rc> { - self.logger.clone() + fn get_log_collector(&self) -> Option>> { + self.log_collector.clone() } - fn get_compute_meter(&self) -> Rc> { + fn get_compute_meter(&self) -> Rc> { self.compute_meter.clone() } fn add_executor(&self, pubkey: &Pubkey, executor: Arc) { diff --git a/program-runtime/src/log_collector.rs b/program-runtime/src/log_collector.rs index 7c5a452a40..f5eaea48e1 100644 --- a/program-runtime/src/log_collector.rs +++ b/program-runtime/src/log_collector.rs @@ -1,48 +1,79 @@ -use std::cell::RefCell; +pub use log; +use std::{cell::RefCell, rc::Rc}; const LOG_MESSAGES_BYTES_LIMIT: usize = 10 * 1000; #[derive(Default)] -struct LogCollectorInner { +pub struct LogCollector { messages: Vec, bytes_written: usize, limit_warning: bool, } -#[derive(Default)] -pub struct LogCollector { - inner: RefCell, -} - impl LogCollector { - pub fn log(&self, message: &str) { - let mut inner = self.inner.borrow_mut(); - let bytes_written = inner.bytes_written.saturating_add(message.len()); + pub fn log(&mut self, message: &str) { + let bytes_written = self.bytes_written.saturating_add(message.len()); if bytes_written >= LOG_MESSAGES_BYTES_LIMIT { - if !inner.limit_warning { - inner.limit_warning = true; - inner.messages.push(String::from("Log truncated")); + if !self.limit_warning { + self.limit_warning = true; + self.messages.push(String::from("Log truncated")); } } else { - inner.bytes_written = bytes_written; - inner.messages.push(message.to_string()); + self.bytes_written = bytes_written; + self.messages.push(message.to_string()); } } + + pub fn new_ref() -> Rc> { + Rc::new(RefCell::new(Self::default())) + } } impl From for Vec { fn from(log_collector: LogCollector) -> Self { - log_collector.inner.into_inner().messages + log_collector.messages } } +/// Convenience macro to log a message with an `Option>>` +#[macro_export] +macro_rules! ic_logger_msg { + ($log_collector:expr, $message:expr) => { + $crate::log_collector::log::debug!("{}", $message); + if let Some(log_collector) = $log_collector.as_ref() { + if let Ok(mut log_collector) = log_collector.try_borrow_mut() { + log_collector.log($message); + } + } + }; + ($log_collector:expr, $fmt:expr, $($arg:tt)*) => { + $crate::log_collector::log::debug!($fmt, $($arg)*); + if let Some(log_collector) = $log_collector.as_ref() { + if let Ok(mut log_collector) = log_collector.try_borrow_mut() { + log_collector.log(&format!($fmt, $($arg)*)); + } + } + }; +} + +/// Convenience macro to log a message with an `InvokeContext` +#[macro_export] +macro_rules! ic_msg { + ($invoke_context:expr, $message:expr) => { + $crate::ic_logger_msg!($invoke_context.get_log_collector(), $message) + }; + ($invoke_context:expr, $fmt:expr, $($arg:tt)*) => { + $crate::ic_logger_msg!($invoke_context.get_log_collector(), $fmt, $($arg)*) + }; +} + #[cfg(test)] pub(crate) mod tests { use super::*; #[test] fn test_log_messages_bytes_limit() { - let lc = LogCollector::default(); + let mut lc = LogCollector::default(); for _i in 0..LOG_MESSAGES_BYTES_LIMIT * 2 { lc.log("x"); diff --git a/program-runtime/src/stable_log.rs b/program-runtime/src/stable_log.rs index f49170a5ce..bd484d555a 100644 --- a/program-runtime/src/stable_log.rs +++ b/program-runtime/src/stable_log.rs @@ -2,7 +2,7 @@ //! //! The format of these log messages should not be modified to avoid breaking downstream consumers //! of program logging -use crate::{ic_logger_msg, invoke_context::Logger}; +use crate::{ic_logger_msg, log_collector::LogCollector}; use itertools::Itertools; use solana_sdk::{instruction::InstructionError, pubkey::Pubkey}; use std::{cell::RefCell, rc::Rc}; @@ -14,8 +14,17 @@ use std::{cell::RefCell, rc::Rc}; /// ```notrust /// "Program
invoke []" /// ``` -pub fn program_invoke(logger: &Rc>, program_id: &Pubkey, invoke_depth: usize) { - ic_logger_msg!(logger, "Program {} invoke [{}]", program_id, invoke_depth); +pub fn program_invoke( + log_collector: &Option>>, + program_id: &Pubkey, + invoke_depth: usize, +) { + ic_logger_msg!( + log_collector, + "Program {} invoke [{}]", + program_id, + invoke_depth + ); } /// Log a message from the program itself. @@ -27,8 +36,8 @@ pub fn program_invoke(logger: &Rc>, program_id: &Pubkey, inv /// ``` /// /// That is, any program-generated output is guaranteed to be prefixed by "Program log: " -pub fn program_log(logger: &Rc>, message: &str) { - ic_logger_msg!(logger, "Program log: {}", message); +pub fn program_log(log_collector: &Option>>, message: &str) { + ic_logger_msg!(log_collector, "Program log: {}", message); } /// Emit a program data. @@ -40,9 +49,9 @@ pub fn program_log(logger: &Rc>, message: &str) { /// ``` /// /// That is, any program-generated output is guaranteed to be prefixed by "Program data: " -pub fn program_data(logger: &Rc>, data: &[&[u8]]) { +pub fn program_data(log_collector: &Option>>, data: &[&[u8]]) { ic_logger_msg!( - logger, + log_collector, "Program data: {}", data.iter().map(base64::encode).join(" ") ); @@ -58,9 +67,13 @@ pub fn program_data(logger: &Rc>, data: &[&[u8]]) { /// ``` /// /// That is, any program-generated output is guaranteed to be prefixed by "Program return: " -pub fn program_return(logger: &Rc>, program_id: &Pubkey, data: &[u8]) { +pub fn program_return( + log_collector: &Option>>, + program_id: &Pubkey, + data: &[u8], +) { ic_logger_msg!( - logger, + log_collector, "Program return: {} {}", program_id, base64::encode(data) @@ -74,8 +87,8 @@ pub fn program_return(logger: &Rc>, program_id: &Pubkey, dat /// ```notrust /// "Program
success" /// ``` -pub fn program_success(logger: &Rc>, program_id: &Pubkey) { - ic_logger_msg!(logger, "Program {} success", program_id); +pub fn program_success(log_collector: &Option>>, program_id: &Pubkey) { + ic_logger_msg!(log_collector, "Program {} success", program_id); } /// Log program execution failure @@ -86,9 +99,9 @@ pub fn program_success(logger: &Rc>, program_id: &Pubkey) { /// "Program
failed: " /// ``` pub fn program_failure( - logger: &Rc>, + log_collector: &Option>>, program_id: &Pubkey, err: &InstructionError, ) { - ic_logger_msg!(logger, "Program {} failed: {}", program_id, err); + ic_logger_msg!(log_collector, "Program {} failed: {}", program_id, err); } diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index 600dc0476a..2c6d571554 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -10,8 +10,8 @@ use { solana_banks_client::start_client, solana_banks_server::banks_server::start_local_server, solana_program_runtime::{ - instruction_processor::InstructionProcessor, invoke_context::ProcessInstructionWithContext, - stable_log, + ic_msg, instruction_processor::InstructionProcessor, + invoke_context::ProcessInstructionWithContext, stable_log, }, solana_runtime::{ bank::{Bank, ExecuteTimings}, @@ -110,9 +110,9 @@ pub fn builtin_process_instruction( ) -> Result<(), InstructionError> { set_invoke_context(invoke_context); - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); let program_id = invoke_context.get_caller()?; - stable_log::program_invoke(&logger, program_id, invoke_context.invoke_depth()); + stable_log::program_invoke(&log_collector, program_id, invoke_context.invoke_depth()); // Skip the processor account let keyed_accounts = &invoke_context.get_keyed_accounts()?[1..]; @@ -165,10 +165,10 @@ pub fn builtin_process_instruction( // Execute the program process_instruction(program_id, &account_infos, input).map_err(|err| { let err = u64::from(err); - stable_log::program_failure(&logger, program_id, &err.into()); + stable_log::program_failure(&log_collector, program_id, &err.into()); err })?; - stable_log::program_success(&logger, program_id); + stable_log::program_success(&log_collector, program_id); // Commit AccountInfo changes back into KeyedAccounts for keyed_account in keyed_accounts { @@ -231,11 +231,7 @@ struct SyscallStubs {} impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { fn sol_log(&self, message: &str) { let invoke_context = get_invoke_context(); - let logger = invoke_context.get_logger(); - let logger = logger.borrow_mut(); - if logger.log_enabled() { - logger.log(&format!("Program log: {}", message)); - } + ic_msg!(invoke_context, "Program log: {}", message); } fn sol_invoke_signed( @@ -250,7 +246,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { // let invoke_context = get_invoke_context(); - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); let caller = *invoke_context.get_caller().expect("get_caller"); let message = Message::new(&[instruction.clone()], None); @@ -266,7 +262,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { .map(|(i, _)| message.is_writable(i, demote_program_write_locks)) .collect::>(); - stable_log::program_invoke(&logger, &program_id, invoke_context.invoke_depth()); + stable_log::program_invoke(&log_collector, &program_id, invoke_context.invoke_depth()); // Convert AccountInfos into Accounts let mut account_indices = Vec::with_capacity(message.account_keys.len()); @@ -363,7 +359,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { } } - stable_log::program_success(&logger, &program_id); + stable_log::program_success(&log_collector, &program_id); Ok(()) } diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 0a78fa67b5..f88647b10c 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -17,7 +17,8 @@ use solana_measure::measure::Measure; use solana_program_runtime::{ ic_logger_msg, ic_msg, instruction_processor::{Executor, InstructionProcessor}, - invoke_context::{ComputeMeter, InvokeContext, Logger}, + invoke_context::{ComputeMeter, InvokeContext}, + log_collector::LogCollector, stable_log, }; use solana_rbpf::{ @@ -209,7 +210,7 @@ fn process_instruction_common( invoke_context: &mut dyn InvokeContext, use_jit: bool, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); let program_id = invoke_context.get_caller()?; let keyed_accounts = invoke_context.get_keyed_accounts()?; @@ -225,7 +226,7 @@ fn process_instruction_common( (second_account?, first_instruction_account + 1) } else { if first_account.executable()? { - ic_logger_msg!(logger, "BPF loader is executable"); + ic_logger_msg!(log_collector, "BPF loader is executable"); return Err(InstructionError::IncorrectProgramId); } (first_account, first_instruction_account) @@ -238,7 +239,10 @@ fn process_instruction_common( ); if !check_loader_id(&program.owner()?) { - ic_logger_msg!(logger, "Executable account not owned by the BPF loader"); + ic_logger_msg!( + log_collector, + "Executable account not owned by the BPF loader" + ); return Err(InstructionError::IncorrectProgramId); } @@ -248,7 +252,10 @@ fn process_instruction_common( } = program.state()? { if programdata_address != *first_account.unsigned_key() { - ic_logger_msg!(logger, "Wrong ProgramData account for this Program account"); + ic_logger_msg!( + log_collector, + "Wrong ProgramData account for this Program account" + ); return Err(InstructionError::InvalidArgument); } if !matches!( @@ -258,12 +265,12 @@ fn process_instruction_common( upgrade_authority_address: _, } ) { - ic_logger_msg!(logger, "Program has been closed"); + ic_logger_msg!(log_collector, "Program has been closed"); return Err(InstructionError::InvalidAccountData); } UpgradeableLoaderState::programdata_data_offset()? } else { - ic_logger_msg!(logger, "Invalid Program account"); + ic_logger_msg!(log_collector, "Invalid Program account"); return Err(InstructionError::InvalidAccountData); } } else { @@ -308,7 +315,7 @@ fn process_instruction_common( use_jit, ) } else { - ic_logger_msg!(logger, "Invalid BPF loader id"); + ic_logger_msg!(log_collector, "Invalid BPF loader id"); Err(InstructionError::IncorrectProgramId) } } @@ -320,7 +327,7 @@ fn process_loader_upgradeable_instruction( invoke_context: &mut dyn InvokeContext, use_jit: bool, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); let program_id = invoke_context.get_caller()?; let keyed_accounts = invoke_context.get_keyed_accounts()?; @@ -329,7 +336,7 @@ fn process_loader_upgradeable_instruction( let buffer = keyed_account_at_index(keyed_accounts, first_instruction_account)?; if UpgradeableLoaderState::Uninitialized != buffer.state()? { - ic_logger_msg!(logger, "Buffer account already initialized"); + ic_logger_msg!(log_collector, "Buffer account already initialized"); return Err(InstructionError::AccountAlreadyInitialized); } @@ -345,19 +352,19 @@ fn process_loader_upgradeable_instruction( if let UpgradeableLoaderState::Buffer { authority_address } = buffer.state()? { if authority_address.is_none() { - ic_logger_msg!(logger, "Buffer is immutable"); + ic_logger_msg!(log_collector, "Buffer is immutable"); return Err(InstructionError::Immutable); // TODO better error code } if authority_address != Some(*authority.unsigned_key()) { - ic_logger_msg!(logger, "Incorrect buffer authority provided"); + ic_logger_msg!(log_collector, "Incorrect buffer authority provided"); return Err(InstructionError::IncorrectAuthority); } if authority.signer_key().is_none() { - ic_logger_msg!(logger, "Buffer authority did not sign"); + ic_logger_msg!(log_collector, "Buffer authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - ic_logger_msg!(logger, "Invalid Buffer account"); + ic_logger_msg!(log_collector, "Invalid Buffer account"); return Err(InstructionError::InvalidAccountData); } write_program_data( @@ -388,15 +395,15 @@ fn process_loader_upgradeable_instruction( // Verify Program account if UpgradeableLoaderState::Uninitialized != program.state()? { - ic_logger_msg!(logger, "Program account already initialized"); + ic_logger_msg!(log_collector, "Program account already initialized"); return Err(InstructionError::AccountAlreadyInitialized); } if program.data_len()? < UpgradeableLoaderState::program_len()? { - ic_logger_msg!(logger, "Program account too small"); + ic_logger_msg!(log_collector, "Program account too small"); return Err(InstructionError::AccountDataTooSmall); } if program.lamports()? < rent.minimum_balance(program.data_len()?) { - ic_logger_msg!(logger, "Program account not rent-exempt"); + ic_logger_msg!(log_collector, "Program account not rent-exempt"); return Err(InstructionError::ExecutableAccountNotRentExempt); } @@ -406,15 +413,15 @@ fn process_loader_upgradeable_instruction( if let UpgradeableLoaderState::Buffer { authority_address } = buffer.state()? { if authority_address != upgrade_authority_address { - ic_logger_msg!(logger, "Buffer and upgrade authority don't match"); + ic_logger_msg!(log_collector, "Buffer and upgrade authority don't match"); return Err(InstructionError::IncorrectAuthority); } if upgrade_authority_signer { - ic_logger_msg!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(log_collector, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - ic_logger_msg!(logger, "Invalid Buffer account"); + ic_logger_msg!(log_collector, "Invalid Buffer account"); return Err(InstructionError::InvalidArgument); } @@ -426,15 +433,18 @@ fn process_loader_upgradeable_instruction( if buffer.data_len()? < UpgradeableLoaderState::buffer_data_offset()? || buffer_data_len == 0 { - ic_logger_msg!(logger, "Buffer account too small"); + ic_logger_msg!(log_collector, "Buffer account too small"); return Err(InstructionError::InvalidAccountData); } if max_data_len < buffer_data_len { - ic_logger_msg!(logger, "Max data length is too small to hold Buffer data"); + ic_logger_msg!( + log_collector, + "Max data length is too small to hold Buffer data" + ); return Err(InstructionError::AccountDataTooSmall); } if programdata_len > MAX_PERMITTED_DATA_LENGTH as usize { - ic_logger_msg!(logger, "Max data length is too large"); + ic_logger_msg!(log_collector, "Max data length is too large"); return Err(InstructionError::InvalidArgument); } @@ -443,7 +453,7 @@ fn process_loader_upgradeable_instruction( let (derived_address, bump_seed) = Pubkey::find_program_address(&[new_program_id.as_ref()], program_id); if derived_address != *programdata.unsigned_key() { - ic_logger_msg!(logger, "ProgramData address is not derived"); + ic_logger_msg!(log_collector, "ProgramData address is not derived"); return Err(InstructionError::InvalidArgument); } @@ -517,7 +527,7 @@ fn process_loader_upgradeable_instruction( buffer.try_account_ref_mut()?.set_lamports(0); } - ic_logger_msg!(logger, "Deployed program {:?}", new_program_id); + ic_logger_msg!(log_collector, "Deployed program {:?}", new_program_id); } UpgradeableLoaderInstruction::Upgrade => { let programdata = keyed_account_at_index(keyed_accounts, first_instruction_account)?; @@ -536,15 +546,15 @@ fn process_loader_upgradeable_instruction( // Verify Program account if !program.executable()? { - ic_logger_msg!(logger, "Program account not executable"); + ic_logger_msg!(log_collector, "Program account not executable"); return Err(InstructionError::AccountNotExecutable); } if !program.is_writable() { - ic_logger_msg!(logger, "Program account not writeable"); + ic_logger_msg!(log_collector, "Program account not writeable"); return Err(InstructionError::InvalidArgument); } if &program.owner()? != program_id { - ic_logger_msg!(logger, "Program account not owned by loader"); + ic_logger_msg!(log_collector, "Program account not owned by loader"); return Err(InstructionError::IncorrectProgramId); } if let UpgradeableLoaderState::Program { @@ -552,11 +562,11 @@ fn process_loader_upgradeable_instruction( } = program.state()? { if programdata_address != *programdata.unsigned_key() { - ic_logger_msg!(logger, "Program and ProgramData account mismatch"); + ic_logger_msg!(log_collector, "Program and ProgramData account mismatch"); return Err(InstructionError::InvalidArgument); } } else { - ic_logger_msg!(logger, "Invalid Program account"); + ic_logger_msg!(log_collector, "Invalid Program account"); return Err(InstructionError::InvalidAccountData); } @@ -566,15 +576,15 @@ fn process_loader_upgradeable_instruction( if let UpgradeableLoaderState::Buffer { authority_address } = buffer.state()? { if authority_address != Some(*authority.unsigned_key()) { - ic_logger_msg!(logger, "Buffer and upgrade authority don't match"); + ic_logger_msg!(log_collector, "Buffer and upgrade authority don't match"); return Err(InstructionError::IncorrectAuthority); } if authority.signer_key().is_none() { - ic_logger_msg!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(log_collector, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - ic_logger_msg!(logger, "Invalid Buffer account"); + ic_logger_msg!(log_collector, "Invalid Buffer account"); return Err(InstructionError::InvalidArgument); } @@ -586,18 +596,21 @@ fn process_loader_upgradeable_instruction( if buffer.data_len()? < UpgradeableLoaderState::buffer_data_offset()? || buffer_data_len == 0 { - ic_logger_msg!(logger, "Buffer account too small"); + ic_logger_msg!(log_collector, "Buffer account too small"); return Err(InstructionError::InvalidAccountData); } // Verify ProgramData account if programdata.data_len()? < UpgradeableLoaderState::programdata_len(buffer_data_len)? { - ic_logger_msg!(logger, "ProgramData account not large enough"); + ic_logger_msg!(log_collector, "ProgramData account not large enough"); return Err(InstructionError::AccountDataTooSmall); } if programdata.lamports()? + buffer.lamports()? < programdata_balance_required { - ic_logger_msg!(logger, "Buffer account balance too low to fund upgrade"); + ic_logger_msg!( + log_collector, + "Buffer account balance too low to fund upgrade" + ); return Err(InstructionError::InsufficientFunds); } if let UpgradeableLoaderState::ProgramData { @@ -606,19 +619,19 @@ fn process_loader_upgradeable_instruction( } = programdata.state()? { if upgrade_authority_address.is_none() { - ic_logger_msg!(logger, "Program not upgradeable"); + ic_logger_msg!(log_collector, "Program not upgradeable"); return Err(InstructionError::Immutable); } if upgrade_authority_address != Some(*authority.unsigned_key()) { - ic_logger_msg!(logger, "Incorrect upgrade authority provided"); + ic_logger_msg!(log_collector, "Incorrect upgrade authority provided"); return Err(InstructionError::IncorrectAuthority); } if authority.signer_key().is_none() { - ic_logger_msg!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(log_collector, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - ic_logger_msg!(logger, "Invalid ProgramData account"); + ic_logger_msg!(log_collector, "Invalid ProgramData account"); return Err(InstructionError::InvalidAccountData); } @@ -662,7 +675,7 @@ fn process_loader_upgradeable_instruction( .try_account_ref_mut()? .set_lamports(programdata_balance_required); - ic_logger_msg!(logger, "Upgraded program {:?}", new_program_id); + ic_logger_msg!(log_collector, "Upgraded program {:?}", new_program_id); } UpgradeableLoaderInstruction::SetAuthority => { let account = keyed_account_at_index(keyed_accounts, first_instruction_account)?; @@ -676,19 +689,19 @@ fn process_loader_upgradeable_instruction( match account.state()? { UpgradeableLoaderState::Buffer { authority_address } => { if new_authority.is_none() { - ic_logger_msg!(logger, "Buffer authority is not optional"); + ic_logger_msg!(log_collector, "Buffer authority is not optional"); return Err(InstructionError::IncorrectAuthority); } if authority_address.is_none() { - ic_logger_msg!(logger, "Buffer is immutable"); + ic_logger_msg!(log_collector, "Buffer is immutable"); return Err(InstructionError::Immutable); } if authority_address != Some(*present_authority.unsigned_key()) { - ic_logger_msg!(logger, "Incorrect buffer authority provided"); + ic_logger_msg!(log_collector, "Incorrect buffer authority provided"); return Err(InstructionError::IncorrectAuthority); } if present_authority.signer_key().is_none() { - ic_logger_msg!(logger, "Buffer authority did not sign"); + ic_logger_msg!(log_collector, "Buffer authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } account.set_state(&UpgradeableLoaderState::Buffer { @@ -700,15 +713,15 @@ fn process_loader_upgradeable_instruction( upgrade_authority_address, } => { if upgrade_authority_address.is_none() { - ic_logger_msg!(logger, "Program not upgradeable"); + ic_logger_msg!(log_collector, "Program not upgradeable"); return Err(InstructionError::Immutable); } if upgrade_authority_address != Some(*present_authority.unsigned_key()) { - ic_logger_msg!(logger, "Incorrect upgrade authority provided"); + ic_logger_msg!(log_collector, "Incorrect upgrade authority provided"); return Err(InstructionError::IncorrectAuthority); } if present_authority.signer_key().is_none() { - ic_logger_msg!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(log_collector, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } account.set_state(&UpgradeableLoaderState::ProgramData { @@ -717,19 +730,22 @@ fn process_loader_upgradeable_instruction( })?; } _ => { - ic_logger_msg!(logger, "Account does not support authorities"); + ic_logger_msg!(log_collector, "Account does not support authorities"); return Err(InstructionError::InvalidArgument); } } - ic_logger_msg!(logger, "New authority {:?}", new_authority); + ic_logger_msg!(log_collector, "New authority {:?}", new_authority); } UpgradeableLoaderInstruction::Close => { let close_account = keyed_account_at_index(keyed_accounts, first_instruction_account)?; let recipient_account = keyed_account_at_index(keyed_accounts, first_instruction_account + 1)?; if close_account.unsigned_key() == recipient_account.unsigned_key() { - ic_logger_msg!(logger, "Recipient is the same as the account being closed"); + ic_logger_msg!( + log_collector, + "Recipient is the same as the account being closed" + ); return Err(InstructionError::InvalidArgument); } @@ -741,7 +757,7 @@ fn process_loader_upgradeable_instruction( close_account.try_account_ref_mut()?.set_lamports(0); ic_logger_msg!( - logger, + log_collector, "Closed Uninitialized {}", close_account.unsigned_key() ); @@ -755,10 +771,14 @@ fn process_loader_upgradeable_instruction( authority, close_account, recipient_account, - logger.clone(), + &log_collector, )?; - ic_logger_msg!(logger, "Closed Buffer {}", close_account.unsigned_key()); + ic_logger_msg!( + log_collector, + "Closed Buffer {}", + close_account.unsigned_key() + ); } UpgradeableLoaderState::ProgramData { slot: _, @@ -768,11 +788,11 @@ fn process_loader_upgradeable_instruction( keyed_account_at_index(keyed_accounts, first_instruction_account + 3)?; if !program_account.is_writable() { - ic_logger_msg!(logger, "Program account is not writable"); + ic_logger_msg!(log_collector, "Program account is not writable"); return Err(InstructionError::InvalidArgument); } if &program_account.owner()? != program_id { - ic_logger_msg!(logger, "Program account not owned by loader"); + ic_logger_msg!(log_collector, "Program account not owned by loader"); return Err(InstructionError::IncorrectProgramId); } @@ -782,7 +802,7 @@ fn process_loader_upgradeable_instruction( } => { if programdata_address != *close_account.unsigned_key() { ic_logger_msg!( - logger, + log_collector, "ProgramData account does not match ProgramData account" ); return Err(InstructionError::InvalidArgument); @@ -797,19 +817,23 @@ fn process_loader_upgradeable_instruction( authority, close_account, recipient_account, - logger.clone(), + &log_collector, )?; } _ => { - ic_logger_msg!(logger, "Invalid Program account"); + ic_logger_msg!(log_collector, "Invalid Program account"); return Err(InstructionError::InvalidArgument); } } - ic_logger_msg!(logger, "Closed Program {}", program_account.unsigned_key()); + ic_logger_msg!( + log_collector, + "Closed Program {}", + program_account.unsigned_key() + ); } _ => { - ic_logger_msg!(logger, "Account does not support closing"); + ic_logger_msg!(log_collector, "Account does not support closing"); return Err(InstructionError::InvalidArgument); } } @@ -824,18 +848,18 @@ fn common_close_account( authority_account: &KeyedAccount, close_account: &KeyedAccount, recipient_account: &KeyedAccount, - logger: Rc>, + log_collector: &Option>>, ) -> Result<(), InstructionError> { if authority_address.is_none() { - ic_logger_msg!(logger, "Account is immutable"); + ic_logger_msg!(log_collector, "Account is immutable"); return Err(InstructionError::Immutable); } if *authority_address != Some(*authority_account.unsigned_key()) { - ic_logger_msg!(logger, "Incorrect authority provided"); + ic_logger_msg!(log_collector, "Incorrect authority provided"); return Err(InstructionError::IncorrectAuthority); } if authority_account.signer_key().is_none() { - ic_logger_msg!(logger, "Authority did not sign"); + ic_logger_msg!(log_collector, "Authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } @@ -901,10 +925,10 @@ fn process_loader_instruction( /// Passed to the VM to enforce the compute budget pub struct ThisInstructionMeter { - pub compute_meter: Rc>, + pub compute_meter: Rc>, } impl ThisInstructionMeter { - fn new(compute_meter: Rc>) -> Self { + fn new(compute_meter: Rc>) -> Self { Self { compute_meter } } } @@ -939,7 +963,7 @@ impl Executor for BpfExecutor { invoke_context: &mut dyn InvokeContext, use_jit: bool, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); let invoke_depth = invoke_context.invoke_depth(); let mut serialize_time = Measure::start("serialize"); @@ -968,14 +992,14 @@ impl Executor for BpfExecutor { ) { Ok(info) => info, Err(e) => { - ic_logger_msg!(logger, "Failed to create BPF VM: {}", e); + ic_logger_msg!(log_collector, "Failed to create BPF VM: {}", e); return Err(InstructionError::ProgramEnvironmentSetupFailure); } }; create_vm_time.stop(); execute_time = Measure::start("execute"); - stable_log::program_invoke(&logger, program_id, invoke_depth); + stable_log::program_invoke(&log_collector, program_id, invoke_depth); let mut instruction_meter = ThisInstructionMeter::new(compute_meter.clone()); let before = compute_meter.borrow().get_remaining(); let result = if use_jit { @@ -985,7 +1009,7 @@ impl Executor for BpfExecutor { }; let after = compute_meter.borrow().get_remaining(); ic_logger_msg!( - logger, + log_collector, "Program {} consumed {} of {} compute units", program_id, before - after, @@ -1001,13 +1025,13 @@ impl Executor for BpfExecutor { drop(vm); let (program_id, return_data) = invoke_context.get_return_data(); if !return_data.is_empty() { - stable_log::program_return(&logger, &program_id, return_data); + stable_log::program_return(&log_collector, &program_id, return_data); } match result { Ok(status) => { if status != SUCCESS { let error: InstructionError = status.into(); - stable_log::program_failure(&logger, &program_id, &error); + stable_log::program_failure(&log_collector, &program_id, &error); return Err(error); } } @@ -1017,11 +1041,11 @@ impl Executor for BpfExecutor { SyscallError::InstructionError(error), )) => error, err => { - ic_logger_msg!(logger, "Program failed to complete: {}", err); + ic_logger_msg!(log_collector, "Program failed to complete: {}", err); InstructionError::ProgramFailedToComplete } }; - stable_log::program_failure(&logger, &program_id, &error); + stable_log::program_failure(&log_collector, &program_id, &error); return Err(error); } } @@ -1044,7 +1068,7 @@ impl Executor for BpfExecutor { deserialize_time.as_us(), ); let program_id = invoke_context.get_caller()?; - stable_log::program_success(&logger, program_id); + stable_log::program_success(&log_collector, program_id); Ok(()) } } diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 0e8cd5cad5..d05ba9732a 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -1,9 +1,10 @@ use crate::{alloc, BpfError}; use alloc::Alloc; use solana_program_runtime::{ - ic_msg, + ic_logger_msg, ic_msg, instruction_processor::InstructionProcessor, - invoke_context::{ComputeMeter, InvokeContext, Logger}, + invoke_context::{ComputeMeter, InvokeContext}, + log_collector::LogCollector, stable_log, }; use solana_rbpf::{ @@ -97,7 +98,7 @@ impl From for EbpfError { trait SyscallConsume { fn consume(&mut self, amount: u64) -> Result<(), EbpfError>; } -impl SyscallConsume for Rc> { +impl SyscallConsume for Rc> { fn consume(&mut self, amount: u64) -> Result<(), EbpfError> { self.try_borrow_mut() .map_err(|_| SyscallError::InvokeContextBorrowFailed)? @@ -229,7 +230,7 @@ pub fn bind_syscall_context_objects<'a>( vm.bind_syscall_context_object( Box::new(SyscallLog { compute_meter: invoke_context.get_compute_meter(), - logger: invoke_context.get_logger(), + log_collector: invoke_context.get_log_collector(), loader_id, }), None, @@ -238,7 +239,7 @@ pub fn bind_syscall_context_objects<'a>( Box::new(SyscallLogU64 { cost: compute_budget.log_64_units, compute_meter: invoke_context.get_compute_meter(), - logger: invoke_context.get_logger(), + log_collector: invoke_context.get_log_collector(), }), None, )?; @@ -247,7 +248,7 @@ pub fn bind_syscall_context_objects<'a>( Box::new(SyscallLogBpfComputeUnits { cost: 0, compute_meter: invoke_context.get_compute_meter(), - logger: invoke_context.get_logger(), + log_collector: invoke_context.get_log_collector(), }), None, )?; @@ -256,7 +257,7 @@ pub fn bind_syscall_context_objects<'a>( Box::new(SyscallLogPubkey { cost: compute_budget.log_pubkey_units, compute_meter: invoke_context.get_compute_meter(), - logger: invoke_context.get_logger(), + log_collector: invoke_context.get_log_collector(), loader_id, }), None, @@ -580,7 +581,7 @@ impl SyscallObject for SyscallAbort { /// Causes the BPF program to be halted immediately /// Log a user's info message pub struct SyscallPanic<'a> { - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallPanic<'a> { @@ -607,8 +608,8 @@ impl<'a> SyscallObject for SyscallPanic<'a> { /// Log a user's info message pub struct SyscallLog<'a> { - compute_meter: Rc>, - logger: Rc>, + compute_meter: Rc>, + log_collector: Option>>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLog<'a> { @@ -630,7 +631,7 @@ impl<'a> SyscallObject for SyscallLog<'a> { len, self.loader_id, &mut |string: &str| { - stable_log::program_log(&self.logger, string); + stable_log::program_log(&self.log_collector, string); Ok(0) }, ), @@ -643,8 +644,8 @@ impl<'a> SyscallObject for SyscallLog<'a> { /// Log 5 64-bit values pub struct SyscallLogU64 { cost: u64, - compute_meter: Rc>, - logger: Rc>, + compute_meter: Rc>, + log_collector: Option>>, } impl SyscallObject for SyscallLogU64 { fn call( @@ -659,7 +660,7 @@ impl SyscallObject for SyscallLogU64 { ) { question_mark!(self.compute_meter.consume(self.cost), result); stable_log::program_log( - &self.logger, + &self.log_collector, &format!( "{:#x}, {:#x}, {:#x}, {:#x}, {:#x}", arg1, arg2, arg3, arg4, arg5 @@ -672,8 +673,8 @@ impl SyscallObject for SyscallLogU64 { /// Log current compute consumption pub struct SyscallLogBpfComputeUnits { cost: u64, - compute_meter: Rc>, - logger: Rc>, + compute_meter: Rc>, + log_collector: Option>>, } impl SyscallObject for SyscallLogBpfComputeUnits { fn call( @@ -687,18 +688,11 @@ impl SyscallObject for SyscallLogBpfComputeUnits { result: &mut Result>, ) { question_mark!(self.compute_meter.consume(self.cost), result); - let logger = question_mark!( - self.logger - .try_borrow_mut() - .map_err(|_| SyscallError::InvokeContextBorrowFailed), - result + ic_logger_msg!( + self.log_collector, + "Program consumption: {} units remaining", + self.compute_meter.borrow().get_remaining() ); - if logger.log_enabled() { - logger.log(&format!( - "Program consumption: {} units remaining", - self.compute_meter.borrow().get_remaining() - )); - } *result = Ok(0); } } @@ -706,8 +700,8 @@ impl SyscallObject for SyscallLogBpfComputeUnits { /// Log 5 64-bit values pub struct SyscallLogPubkey<'a> { cost: u64, - compute_meter: Rc>, - logger: Rc>, + compute_meter: Rc>, + log_collector: Option>>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLogPubkey<'a> { @@ -726,7 +720,7 @@ impl<'a> SyscallObject for SyscallLogPubkey<'a> { translate_type::(memory_mapping, pubkey_addr, self.loader_id,), result ); - stable_log::program_log(&self.logger, &pubkey.to_string()); + stable_log::program_log(&self.log_collector, &pubkey.to_string()); *result = Ok(0); } } @@ -809,7 +803,7 @@ fn translate_and_check_program_address_inputs<'a>( /// Create a program address struct SyscallCreateProgramAddress<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallCreateProgramAddress<'a> { @@ -855,7 +849,7 @@ impl<'a> SyscallObject for SyscallCreateProgramAddress<'a> { /// Create a program address struct SyscallTryFindProgramAddress<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallTryFindProgramAddress<'a> { @@ -916,7 +910,7 @@ impl<'a> SyscallObject for SyscallTryFindProgramAddress<'a> { pub struct SyscallSha256<'a> { sha256_base_cost: u64, sha256_byte_cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallSha256<'a> { @@ -1097,7 +1091,7 @@ impl<'a> SyscallObject for SyscallGetRentSysvar<'a> { pub struct SyscallKeccak256<'a> { base_cost: u64, byte_cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallKeccak256<'a> { @@ -1158,7 +1152,7 @@ fn check_overlapping(src_addr: u64, dst_addr: u64, n: u64) -> bool { /// memcpy pub struct SyscallMemcpy<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallMemcpy<'a> { @@ -1195,7 +1189,7 @@ impl<'a> SyscallObject for SyscallMemcpy<'a> { /// memmove pub struct SyscallMemmove<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallMemmove<'a> { @@ -1227,7 +1221,7 @@ impl<'a> SyscallObject for SyscallMemmove<'a> { /// memcmp pub struct SyscallMemcmp<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallMemcmp<'a> { @@ -1272,7 +1266,7 @@ impl<'a> SyscallObject for SyscallMemcmp<'a> { /// memset pub struct SyscallMemset<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallMemset<'a> { @@ -1301,7 +1295,7 @@ impl<'a> SyscallObject for SyscallMemset<'a> { /// secp256k1_recover pub struct SyscallSecp256k1Recover<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, libsecp256k1_0_5_upgrade_enabled: bool, } @@ -1392,7 +1386,7 @@ impl<'a> SyscallObject for SyscallSecp256k1Recover<'a> { pub struct SyscallBlake3<'a> { base_cost: u64, byte_cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallBlake3<'a> { @@ -2429,9 +2423,9 @@ impl<'a> SyscallObject for SyscallLogData<'a> { )); } - let logger = invoke_context.get_logger(); + let log_collector = invoke_context.get_log_collector(); - stable_log::program_data(&logger, &fields); + stable_log::program_data(&log_collector, &fields); *result = Ok(0); } @@ -2441,7 +2435,7 @@ impl<'a> SyscallObject for SyscallLogData<'a> { mod tests { use super::*; use solana_program_runtime::{ - invoke_context::{ThisComputeMeter, ThisInvokeContext, ThisLogger}, + invoke_context::{ComputeMeter, ThisInvokeContext}, log_collector::LogCollector, }; use solana_rbpf::{ @@ -2776,7 +2770,7 @@ mod tests { ) .unwrap(); - let compute_meter = ThisComputeMeter::new_ref(string.len() as u64 - 1); + let compute_meter = ComputeMeter::new_ref(string.len() as u64 - 1); let mut syscall_panic = SyscallPanic { compute_meter, loader_id: &bpf_loader::id(), @@ -2798,7 +2792,7 @@ mod tests { result ); - let compute_meter = ThisComputeMeter::new_ref(string.len() as u64); + let compute_meter = ComputeMeter::new_ref(string.len() as u64); let mut syscall_panic = SyscallPanic { compute_meter, loader_id: &bpf_loader::id(), @@ -2835,12 +2829,12 @@ mod tests { &config, ) .unwrap(); - let log = Rc::new(LogCollector::default()); + let log = LogCollector::new_ref(); { let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref(string.len() as u64), - logger: ThisLogger::new_ref(Some(log.clone())), + compute_meter: ComputeMeter::new_ref(string.len() as u64), + log_collector: Some(log.clone()), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2857,15 +2851,15 @@ mod tests { } let log: Vec = match Rc::try_unwrap(log) { - Ok(log) => log.into(), + Ok(log) => log.into_inner().into(), Err(_) => panic!("Unwrap failed"), }; assert_eq!(log.len(), 1); assert_eq!(log[0], "Program log: Gaggablaghblagh!"); let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref(string.len() as u64 * 3), - logger: ThisLogger::new_ref(None), + compute_meter: ComputeMeter::new_ref(string.len() as u64 * 3), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2902,8 +2896,8 @@ mod tests { ); let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref((string.len() as u64 * 2) - 1), - logger: ThisLogger::new_ref(None), + compute_meter: ComputeMeter::new_ref((string.len() as u64 * 2) - 1), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2937,13 +2931,13 @@ mod tests { #[test] fn test_syscall_sol_log_u64() { - let log = Rc::new(LogCollector::default()); + let log = LogCollector::new_ref(); { let mut syscall_sol_log_u64 = SyscallLogU64 { cost: 0, - compute_meter: ThisComputeMeter::new_ref(std::u64::MAX), - logger: ThisLogger::new_ref(Some(log.clone())), + compute_meter: ComputeMeter::new_ref(std::u64::MAX), + log_collector: Some(log.clone()), }; let config = Config::default(); let memory_mapping = MemoryMapping::new::(vec![], &config).unwrap(); @@ -2953,7 +2947,7 @@ mod tests { } let log: Vec = match Rc::try_unwrap(log) { - Ok(log) => log.into(), + Ok(log) => log.into_inner().into(), Err(_) => panic!("Unwrap failed"), }; assert_eq!(log.len(), 1); @@ -2979,13 +2973,13 @@ mod tests { &config, ) .unwrap(); - let log = Rc::new(LogCollector::default()); + let log = LogCollector::new_ref(); { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, - compute_meter: ThisComputeMeter::new_ref(1), - logger: ThisLogger::new_ref(Some(log.clone())), + compute_meter: ComputeMeter::new_ref(1), + log_collector: Some(log.clone()), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2994,7 +2988,7 @@ mod tests { } let log: Vec = match Rc::try_unwrap(log) { - Ok(log) => log.into(), + Ok(log) => log.into_inner().into(), Err(_) => panic!("Unwrap failed"), }; assert_eq!(log.len(), 1); @@ -3005,8 +2999,8 @@ mod tests { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, - compute_meter: ThisComputeMeter::new_ref(1), - logger: ThisLogger::new_ref(None), + compute_meter: ComputeMeter::new_ref(1), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -3210,7 +3204,7 @@ mod tests { &config, ) .unwrap(); - let compute_meter = ThisComputeMeter::new_ref((bytes1.len() + bytes2.len()) as u64); + let compute_meter = ComputeMeter::new_ref((bytes1.len() + bytes2.len()) as u64); let mut syscall = SyscallSha256 { sha256_base_cost: 0, sha256_byte_cost: 2, @@ -3564,7 +3558,7 @@ mod tests { ) -> Result> { let mut syscall = SyscallCreateProgramAddress { cost: 1, - compute_meter: ThisComputeMeter::new_ref(remaining), + compute_meter: ComputeMeter::new_ref(remaining), loader_id: &bpf_loader::id(), }; let (address, _) = call_program_address_common(seeds, program_id, &mut syscall)?; @@ -3578,7 +3572,7 @@ mod tests { ) -> Result<(Pubkey, u8), EbpfError> { let mut syscall = SyscallTryFindProgramAddress { cost: 1, - compute_meter: ThisComputeMeter::new_ref(remaining), + compute_meter: ComputeMeter::new_ref(remaining), loader_id: &bpf_loader::id(), }; call_program_address_common(seeds, program_id, &mut syscall) diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 9b2828e084..33e7468e42 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -102,7 +102,7 @@ use solana_sdk::{ hash::{extend_and_hash, hashv, Hash}, incinerator, inflation::Inflation, - instruction::{CompiledInstruction, InstructionError}, + instruction::CompiledInstruction, lamports::LamportsError, message::SanitizedMessage, native_loader, @@ -426,28 +426,6 @@ impl CachedExecutors { } } -pub struct TransactionComputeMeter { - remaining: u64, -} -impl TransactionComputeMeter { - pub fn new(cap: u64) -> Self { - Self { remaining: cap } - } -} -impl ComputeMeter for TransactionComputeMeter { - fn consume(&mut self, amount: u64) -> std::result::Result<(), InstructionError> { - let exceeded = self.remaining < amount; - self.remaining = self.remaining.saturating_sub(amount); - if exceeded { - return Err(InstructionError::ComputationalBudgetExceeded); - } - Ok(()) - } - fn get_remaining(&self) -> u64 { - self.remaining - } -} - #[derive(Debug)] pub struct BankRc { /// where all the Accounts are stored @@ -3703,24 +3681,6 @@ impl Bank { Ok(()) } - fn collect_log_messages( - log_collector: Option>, - ) -> Option { - log_collector.and_then(|log_collector| Rc::try_unwrap(log_collector).map(Into::into).ok()) - } - - fn compile_recorded_instructions( - instruction_recorders: Option>, - message: &SanitizedMessage, - ) -> Option { - instruction_recorders.and_then(|instruction_recorders| { - instruction_recorders - .into_iter() - .map(|r| r.compile_instructions(message)) - .collect() - }) - } - /// Get any cached executors needed by the transaction fn get_executors( &self, @@ -3882,14 +3842,12 @@ impl Bank { }; let log_collector = if enable_log_recording { - Some(Rc::new(LogCollector::default())) + Some(LogCollector::new_ref()) } else { None }; - let compute_meter = Rc::new(RefCell::new(TransactionComputeMeter::new( - compute_budget.max_units, - ))); + let compute_meter = ComputeMeter::new_ref(compute_budget.max_units); let (blockhash, lamports_per_signature) = { let blockhash_queue = self.blockhash_queue.read().unwrap(); @@ -3925,11 +3883,21 @@ impl Bank { process_result = Err(TransactionError::UnsupportedVersion); } - transaction_log_messages.push(Self::collect_log_messages(log_collector)); - inner_instructions.push(Self::compile_recorded_instructions( - instruction_recorders, - tx.message(), - )); + let log_messages: Option = + log_collector.and_then(|log_collector| { + Rc::try_unwrap(log_collector) + .map(|log_collector| log_collector.into_inner().into()) + .ok() + }); + transaction_log_messages.push(log_messages); + let inner_instruction_list: Option = + instruction_recorders.and_then(|instruction_recorders| { + instruction_recorders + .into_iter() + .map(|r| r.compile_instructions(tx.message())) + .collect() + }); + inner_instructions.push(inner_instruction_list); if let Err(e) = Self::refcells_to_accounts( &mut loaded_transaction.accounts, diff --git a/runtime/src/builtins.rs b/runtime/src/builtins.rs index a32b7122f8..b5a38edb86 100644 --- a/runtime/src/builtins.rs +++ b/runtime/src/builtins.rs @@ -17,7 +17,7 @@ fn process_instruction_with_program_logging( instruction_data: &[u8], invoke_context: &mut dyn InvokeContext, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); + let logger = invoke_context.get_log_collector(); let program_id = invoke_context.get_caller()?; stable_log::program_invoke(&logger, program_id, invoke_context.invoke_depth()); diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index d5a840e742..02a8425c7d 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -45,12 +45,12 @@ impl MessageProcessor { program_indices: &[Vec], accounts: &[(Pubkey, Rc>)], rent: Rent, - log_collector: Option>, + log_collector: Option>>, executors: Rc>, instruction_recorders: Option<&[InstructionRecorder]>, feature_set: Arc, compute_budget: ComputeBudget, - compute_meter: Rc>, + compute_meter: Rc>, timings: &mut ExecuteDetailsTimings, sysvars: &[(Pubkey, Vec)], blockhash: Hash, @@ -134,7 +134,7 @@ impl MessageProcessor { mod tests { use super::*; use crate::rent_collector::RentCollector; - use solana_program_runtime::invoke_context::ThisComputeMeter; + use solana_program_runtime::invoke_context::ComputeMeter; use solana_sdk::{ account::ReadableAccount, instruction::{AccountMeta, Instruction, InstructionError}, @@ -244,7 +244,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -274,7 +274,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -308,7 +308,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -451,7 +451,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -485,7 +485,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -516,7 +516,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(), @@ -572,7 +572,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - ThisComputeMeter::new_ref(std::i64::MAX as u64), + ComputeMeter::new_ref(std::i64::MAX as u64), &mut ExecuteDetailsTimings::default(), &[], Hash::default(),