From 19094b45a20c7da30bfbf8c09a67d103d43fd97d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Mon, 22 Nov 2021 18:30:09 +0100 Subject: [PATCH 1/6] Unifies dyn Trait ComputeMeter, ThisComputeMeter and TransactionComputeMeter. --- program-runtime/src/invoke_context.rs | 33 +++++++--------- programs/bpf_loader/src/lib.rs | 4 +- programs/bpf_loader/src/syscalls.rs | 56 +++++++++++++-------------- runtime/src/bank.rs | 28 +------------- runtime/src/message_processor.rs | 18 ++++----- 5 files changed, 54 insertions(+), 85 deletions(-) diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 79201397dbf23b..d599c879dac204 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -23,18 +23,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,11 +36,11 @@ 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 })) } @@ -150,7 +144,7 @@ pub struct ThisInvokeContext<'a> { logger: Rc>, compute_budget: ComputeBudget, current_compute_budget: ComputeBudget, - compute_meter: Rc>, + compute_meter: Rc>, executors: Rc>, instruction_recorders: Option<&'a [InstructionRecorder]>, feature_set: Arc, @@ -168,7 +162,7 @@ impl<'a> ThisInvokeContext<'a> { sysvars: &'a [(Pubkey, Vec)], log_collector: Option>, compute_budget: ComputeBudget, - compute_meter: Rc>, + compute_meter: Rc>, executors: Rc>, instruction_recorders: Option<&'a [InstructionRecorder]>, feature_set: Arc, @@ -210,7 +204,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, @@ -275,7 +269,7 @@ pub trait InvokeContext { /// Get this invocation's logger fn get_logger(&self) -> Rc>; /// Get this invocation's compute meter - fn get_compute_meter(&self) -> Rc>; + 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 +343,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()); @@ -590,7 +583,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { fn get_logger(&self) -> Rc> { self.logger.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/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 0a78fa67b55186..840e109765af4b 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -901,10 +901,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 } } } diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 0e8cd5cad58263..9de5a15997688e 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -97,7 +97,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)? @@ -580,7 +580,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,7 +607,7 @@ impl<'a> SyscallObject for SyscallPanic<'a> { /// Log a user's info message pub struct SyscallLog<'a> { - compute_meter: Rc>, + compute_meter: Rc>, logger: Rc>, loader_id: &'a Pubkey, } @@ -643,7 +643,7 @@ impl<'a> SyscallObject for SyscallLog<'a> { /// Log 5 64-bit values pub struct SyscallLogU64 { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, logger: Rc>, } impl SyscallObject for SyscallLogU64 { @@ -672,7 +672,7 @@ impl SyscallObject for SyscallLogU64 { /// Log current compute consumption pub struct SyscallLogBpfComputeUnits { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, logger: Rc>, } impl SyscallObject for SyscallLogBpfComputeUnits { @@ -706,7 +706,7 @@ impl SyscallObject for SyscallLogBpfComputeUnits { /// Log 5 64-bit values pub struct SyscallLogPubkey<'a> { cost: u64, - compute_meter: Rc>, + compute_meter: Rc>, logger: Rc>, loader_id: &'a Pubkey, } @@ -809,7 +809,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 +855,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 +916,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 +1097,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 +1158,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 +1195,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 +1227,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 +1272,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 +1301,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 +1392,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> { @@ -2441,7 +2441,7 @@ impl<'a> SyscallObject for SyscallLogData<'a> { mod tests { use super::*; use solana_program_runtime::{ - invoke_context::{ThisComputeMeter, ThisInvokeContext, ThisLogger}, + invoke_context::{ComputeMeter, ThisInvokeContext, ThisLogger}, log_collector::LogCollector, }; use solana_rbpf::{ @@ -2776,7 +2776,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 +2798,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(), @@ -2839,7 +2839,7 @@ mod tests { { let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref(string.len() as u64), + compute_meter: ComputeMeter::new_ref(string.len() as u64), logger: ThisLogger::new_ref(Some(log.clone())), loader_id: &bpf_loader::id(), }; @@ -2864,7 +2864,7 @@ mod tests { assert_eq!(log[0], "Program log: Gaggablaghblagh!"); let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref(string.len() as u64 * 3), + compute_meter: ComputeMeter::new_ref(string.len() as u64 * 3), logger: ThisLogger::new_ref(None), loader_id: &bpf_loader::id(), }; @@ -2902,7 +2902,7 @@ mod tests { ); let mut syscall_sol_log = SyscallLog { - compute_meter: ThisComputeMeter::new_ref((string.len() as u64 * 2) - 1), + compute_meter: ComputeMeter::new_ref((string.len() as u64 * 2) - 1), logger: ThisLogger::new_ref(None), loader_id: &bpf_loader::id(), }; @@ -2942,7 +2942,7 @@ mod tests { { let mut syscall_sol_log_u64 = SyscallLogU64 { cost: 0, - compute_meter: ThisComputeMeter::new_ref(std::u64::MAX), + compute_meter: ComputeMeter::new_ref(std::u64::MAX), logger: ThisLogger::new_ref(Some(log.clone())), }; let config = Config::default(); @@ -2984,7 +2984,7 @@ mod tests { { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, - compute_meter: ThisComputeMeter::new_ref(1), + compute_meter: ComputeMeter::new_ref(1), logger: ThisLogger::new_ref(Some(log.clone())), loader_id: &bpf_loader::id(), }; @@ -3005,7 +3005,7 @@ mod tests { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, - compute_meter: ThisComputeMeter::new_ref(1), + compute_meter: ComputeMeter::new_ref(1), logger: ThisLogger::new_ref(None), loader_id: &bpf_loader::id(), }; @@ -3210,7 +3210,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 +3564,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 +3578,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 9b2828e0848e88..a9569a13db1ed1 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 @@ -3887,9 +3865,7 @@ impl Bank { 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(); diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index d5a840e74232f2..3dfca07f028ba1 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -50,7 +50,7 @@ impl MessageProcessor { 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(), From ba7863bee46e152732dcc596e3297b3d050c9104 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Mon, 22 Nov 2021 18:50:35 +0100 Subject: [PATCH 2/6] Unifies dyn Trait Logger and ThisLogger. --- program-runtime/src/invoke_context.rs | 36 +++++++++++---------------- program-runtime/src/stable_log.rs | 16 +++++------- programs/bpf_loader/src/lib.rs | 2 +- programs/bpf_loader/src/syscalls.rs | 22 ++++++++-------- 4 files changed, 33 insertions(+), 43 deletions(-) diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index d599c879dac204..0c303ec035abab 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -47,37 +47,31 @@ impl ComputeMeter { } /// 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 { +pub struct Logger { log_collector: Option>, } -impl Logger for ThisLogger { - fn log_enabled(&self) -> bool { +impl Logger { + /// Is logging enabled + pub fn log_enabled(&self) -> bool { log_enabled!(log::Level::Info) || self.log_collector.is_some() } - fn log(&self, message: &str) { + /// Log a message. + /// + /// Unless explicitly stated, log messages are not considered stable and may change in the + /// future as necessary + pub fn log(&self, message: &str) { debug!("{}", message); if let Some(log_collector) = &self.log_collector { log_collector.log(message); } } -} -impl ThisLogger { + /// Construct a new one pub fn new_ref(log_collector: Option>) -> Rc> { Rc::new(RefCell::new(Self { log_collector })) } } -/// Convenience macro to log a message with an `Rc>` +/// Convenience macro to log a message with an `Rc>` #[macro_export] macro_rules! ic_logger_msg { ($logger:expr, $message:expr) => { @@ -141,7 +135,7 @@ pub struct ThisInvokeContext<'a> { accounts: &'a [(Pubkey, Rc>)], programs: &'a [(Pubkey, ProcessInstructionWithContext)], sysvars: &'a [(Pubkey, Vec)], - logger: Rc>, + logger: Rc>, compute_budget: ComputeBudget, current_compute_budget: ComputeBudget, compute_meter: Rc>, @@ -177,7 +171,7 @@ impl<'a> ThisInvokeContext<'a> { accounts, programs, sysvars, - logger: ThisLogger::new_ref(log_collector), + logger: Logger::new_ref(log_collector), current_compute_budget: compute_budget, compute_budget, compute_meter, @@ -267,7 +261,7 @@ pub trait InvokeContext { /// Get a list of built-in programs fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)]; /// Get this invocation's logger - fn get_logger(&self) -> Rc>; + fn get_logger(&self) -> Rc>; /// Get this invocation's compute meter fn get_compute_meter(&self) -> Rc>; /// Loaders may need to do work in order to execute a program. Cache @@ -580,7 +574,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)] { self.programs } - fn get_logger(&self) -> Rc> { + fn get_logger(&self) -> Rc> { self.logger.clone() } fn get_compute_meter(&self) -> Rc> { diff --git a/program-runtime/src/stable_log.rs b/program-runtime/src/stable_log.rs index f49170a5ce714d..fbf55361a9456e 100644 --- a/program-runtime/src/stable_log.rs +++ b/program-runtime/src/stable_log.rs @@ -14,7 +14,7 @@ use std::{cell::RefCell, rc::Rc}; /// ```notrust /// "Program
invoke []" /// ``` -pub fn program_invoke(logger: &Rc>, program_id: &Pubkey, invoke_depth: usize) { +pub fn program_invoke(logger: &Rc>, program_id: &Pubkey, invoke_depth: usize) { ic_logger_msg!(logger, "Program {} invoke [{}]", program_id, invoke_depth); } @@ -27,7 +27,7 @@ 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) { +pub fn program_log(logger: &Rc>, message: &str) { ic_logger_msg!(logger, "Program log: {}", message); } @@ -40,7 +40,7 @@ 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(logger: &Rc>, data: &[&[u8]]) { ic_logger_msg!( logger, "Program data: {}", @@ -58,7 +58,7 @@ 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(logger: &Rc>, program_id: &Pubkey, data: &[u8]) { ic_logger_msg!( logger, "Program return: {} {}", @@ -74,7 +74,7 @@ pub fn program_return(logger: &Rc>, program_id: &Pubkey, dat /// ```notrust /// "Program
success" /// ``` -pub fn program_success(logger: &Rc>, program_id: &Pubkey) { +pub fn program_success(logger: &Rc>, program_id: &Pubkey) { ic_logger_msg!(logger, "Program {} success", program_id); } @@ -85,10 +85,6 @@ pub fn program_success(logger: &Rc>, program_id: &Pubkey) { /// ```notrust /// "Program
failed: " /// ``` -pub fn program_failure( - logger: &Rc>, - program_id: &Pubkey, - err: &InstructionError, -) { +pub fn program_failure(logger: &Rc>, program_id: &Pubkey, err: &InstructionError) { ic_logger_msg!(logger, "Program {} failed: {}", program_id, err); } diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 840e109765af4b..5212dd2d0a1f60 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -824,7 +824,7 @@ fn common_close_account( authority_account: &KeyedAccount, close_account: &KeyedAccount, recipient_account: &KeyedAccount, - logger: Rc>, + logger: Rc>, ) -> Result<(), InstructionError> { if authority_address.is_none() { ic_logger_msg!(logger, "Account is immutable"); diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 9de5a15997688e..acfc6fc3918161 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -608,7 +608,7 @@ impl<'a> SyscallObject for SyscallPanic<'a> { /// Log a user's info message pub struct SyscallLog<'a> { compute_meter: Rc>, - logger: Rc>, + logger: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLog<'a> { @@ -644,7 +644,7 @@ impl<'a> SyscallObject for SyscallLog<'a> { pub struct SyscallLogU64 { cost: u64, compute_meter: Rc>, - logger: Rc>, + logger: Rc>, } impl SyscallObject for SyscallLogU64 { fn call( @@ -673,7 +673,7 @@ impl SyscallObject for SyscallLogU64 { pub struct SyscallLogBpfComputeUnits { cost: u64, compute_meter: Rc>, - logger: Rc>, + logger: Rc>, } impl SyscallObject for SyscallLogBpfComputeUnits { fn call( @@ -707,7 +707,7 @@ impl SyscallObject for SyscallLogBpfComputeUnits { pub struct SyscallLogPubkey<'a> { cost: u64, compute_meter: Rc>, - logger: Rc>, + logger: Rc>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLogPubkey<'a> { @@ -2441,7 +2441,7 @@ impl<'a> SyscallObject for SyscallLogData<'a> { mod tests { use super::*; use solana_program_runtime::{ - invoke_context::{ComputeMeter, ThisInvokeContext, ThisLogger}, + invoke_context::{ComputeMeter, Logger, ThisInvokeContext}, log_collector::LogCollector, }; use solana_rbpf::{ @@ -2840,7 +2840,7 @@ mod tests { { let mut syscall_sol_log = SyscallLog { compute_meter: ComputeMeter::new_ref(string.len() as u64), - logger: ThisLogger::new_ref(Some(log.clone())), + logger: Logger::new_ref(Some(log.clone())), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2865,7 +2865,7 @@ mod tests { let mut syscall_sol_log = SyscallLog { compute_meter: ComputeMeter::new_ref(string.len() as u64 * 3), - logger: ThisLogger::new_ref(None), + logger: Logger::new_ref(None), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2903,7 +2903,7 @@ mod tests { let mut syscall_sol_log = SyscallLog { compute_meter: ComputeMeter::new_ref((string.len() as u64 * 2) - 1), - logger: ThisLogger::new_ref(None), + logger: Logger::new_ref(None), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2943,7 +2943,7 @@ mod tests { let mut syscall_sol_log_u64 = SyscallLogU64 { cost: 0, compute_meter: ComputeMeter::new_ref(std::u64::MAX), - logger: ThisLogger::new_ref(Some(log.clone())), + logger: Logger::new_ref(Some(log.clone())), }; let config = Config::default(); let memory_mapping = MemoryMapping::new::(vec![], &config).unwrap(); @@ -2985,7 +2985,7 @@ mod tests { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, compute_meter: ComputeMeter::new_ref(1), - logger: ThisLogger::new_ref(Some(log.clone())), + logger: Logger::new_ref(Some(log.clone())), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -3006,7 +3006,7 @@ mod tests { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, compute_meter: ComputeMeter::new_ref(1), - logger: ThisLogger::new_ref(None), + logger: Logger::new_ref(None), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); From 461daec8432ef97312c4243365d41dc8f9736f24 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Mon, 22 Nov 2021 19:21:56 +0100 Subject: [PATCH 3/6] Moves Logger to log_collector.rs --- program-runtime/src/invoke_context.rs | 58 +-------------------------- program-runtime/src/log_collector.rs | 58 ++++++++++++++++++++++++++- program-runtime/src/stable_log.rs | 2 +- programs/bpf_loader/src/lib.rs | 3 +- programs/bpf_loader/src/syscalls.rs | 7 ++-- 5 files changed, 65 insertions(+), 63 deletions(-) diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 0c303ec035abab..88188c9bf08071 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -2,9 +2,8 @@ use crate::{ ic_logger_msg, ic_msg, instruction_processor::{ExecuteDetailsTimings, Executor, Executors, PreAccount}, instruction_recorder::InstructionRecorder, - log_collector::LogCollector, + log_collector::{LogCollector, Logger}, }; -use log::*; use solana_sdk::{ account::{AccountSharedData, ReadableAccount}, compute_budget::ComputeBudget, @@ -46,61 +45,6 @@ impl ComputeMeter { } } -/// Log messages -pub struct Logger { - log_collector: Option>, -} -impl Logger { - /// Is logging enabled - pub fn log_enabled(&self) -> bool { - log_enabled!(log::Level::Info) || self.log_collector.is_some() - } - /// Log a message. - /// - /// Unless explicitly stated, log messages are not considered stable and may change in the - /// future as necessary - pub fn log(&self, message: &str) { - debug!("{}", message); - if let Some(log_collector) = &self.log_collector { - log_collector.log(message); - } - } - /// Construct a new one - 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>, diff --git a/program-runtime/src/log_collector.rs b/program-runtime/src/log_collector.rs index 7c5a452a406304..ea2626f7afc7f9 100644 --- a/program-runtime/src/log_collector.rs +++ b/program-runtime/src/log_collector.rs @@ -1,4 +1,5 @@ -use std::cell::RefCell; +use std::{cell::RefCell, rc::Rc}; +use log::*; const LOG_MESSAGES_BYTES_LIMIT: usize = 10 * 1000; @@ -36,6 +37,61 @@ impl From for Vec { } } +/// Log messages +pub struct Logger { + log_collector: Option>, +} +impl Logger { + /// Is logging enabled + pub fn log_enabled(&self) -> bool { + log_enabled!(log::Level::Info) || self.log_collector.is_some() + } + /// Log a message. + /// + /// Unless explicitly stated, log messages are not considered stable and may change in the + /// future as necessary + pub fn log(&self, message: &str) { + debug!("{}", message); + if let Some(log_collector) = &self.log_collector { + log_collector.log(message); + } + } + /// Construct a new one + 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)*) + }; +} + #[cfg(test)] pub(crate) mod tests { use super::*; diff --git a/program-runtime/src/stable_log.rs b/program-runtime/src/stable_log.rs index fbf55361a9456e..47fedfaf3f7f0e 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::Logger}; use itertools::Itertools; use solana_sdk::{instruction::InstructionError, pubkey::Pubkey}; use std::{cell::RefCell, rc::Rc}; diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 5212dd2d0a1f60..ab623d02abdb21 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::Logger, stable_log, }; use solana_rbpf::{ diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index acfc6fc3918161..3aa33414dd7fb2 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -3,7 +3,8 @@ use alloc::Alloc; use solana_program_runtime::{ ic_msg, instruction_processor::InstructionProcessor, - invoke_context::{ComputeMeter, InvokeContext, Logger}, + invoke_context::{ComputeMeter, InvokeContext}, + log_collector::Logger, stable_log, }; use solana_rbpf::{ @@ -2441,8 +2442,8 @@ impl<'a> SyscallObject for SyscallLogData<'a> { mod tests { use super::*; use solana_program_runtime::{ - invoke_context::{ComputeMeter, Logger, ThisInvokeContext}, - log_collector::LogCollector, + invoke_context::{ComputeMeter, ThisInvokeContext}, + log_collector::{LogCollector, Logger}, }; use solana_rbpf::{ ebpf::HOST_ALIGN, memory_region::MemoryRegion, user_error::UserError, vm::Config, From fce896be3cfb6c1cf562f8abb9a7823d19d3aa2c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Mon, 22 Nov 2021 21:22:41 +0100 Subject: [PATCH 4/6] Unifies Logger and LogCollector. --- program-runtime/src/invoke_context.rs | 29 +++-- program-runtime/src/log_collector.rs | 53 +++----- program-runtime/src/stable_log.rs | 43 +++++-- program-test/src/lib.rs | 24 ++-- programs/bpf_loader/src/lib.rs | 171 +++++++++++++++----------- programs/bpf_loader/src/syscalls.rs | 71 +++++------ runtime/src/bank.rs | 40 +++--- runtime/src/builtins.rs | 2 +- runtime/src/message_processor.rs | 2 +- 9 files changed, 220 insertions(+), 215 deletions(-) diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 88188c9bf08071..fa1542f92cbaf2 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -2,7 +2,7 @@ use crate::{ ic_logger_msg, ic_msg, instruction_processor::{ExecuteDetailsTimings, Executor, Executors, PreAccount}, instruction_recorder::InstructionRecorder, - log_collector::{LogCollector, Logger}, + log_collector::LogCollector, }; use solana_sdk::{ account::{AccountSharedData, ReadableAccount}, @@ -79,7 +79,7 @@ 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>, @@ -98,7 +98,7 @@ 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>, executors: Rc>, @@ -115,7 +115,7 @@ impl<'a> ThisInvokeContext<'a> { accounts, programs, sysvars, - logger: Logger::new_ref(log_collector), + log_collector, current_compute_budget: compute_budget, compute_budget, compute_meter, @@ -204,9 +204,9 @@ 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 + /// 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 @@ -395,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 @@ -431,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; @@ -466,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 @@ -518,8 +523,8 @@ 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> { self.compute_meter.clone() diff --git a/program-runtime/src/log_collector.rs b/program-runtime/src/log_collector.rs index ea2626f7afc7f9..a5c0e7548fe37c 100644 --- a/program-runtime/src/log_collector.rs +++ b/program-runtime/src/log_collector.rs @@ -1,5 +1,4 @@ use std::{cell::RefCell, rc::Rc}; -use log::*; const LOG_MESSAGES_BYTES_LIMIT: usize = 10 * 1000; @@ -29,6 +28,11 @@ impl LogCollector { inner.messages.push(message.to_string()); } } + pub fn new_ref() -> Rc> { + Rc::new(RefCell::new(Self { + inner: RefCell::new(LogCollectorInner::default()), + })) + } } impl From for Vec { @@ -37,45 +41,20 @@ impl From for Vec { } } -/// Log messages -pub struct Logger { - log_collector: Option>, -} -impl Logger { - /// Is logging enabled - pub fn log_enabled(&self) -> bool { - log_enabled!(log::Level::Info) || self.log_collector.is_some() - } - /// Log a message. - /// - /// Unless explicitly stated, log messages are not considered stable and may change in the - /// future as necessary - pub fn log(&self, message: &str) { - debug!("{}", message); - if let Some(log_collector) = &self.log_collector { - log_collector.log(message); - } - } - /// Construct a new one - pub fn new_ref(log_collector: Option>) -> Rc> { - Rc::new(RefCell::new(Self { log_collector })) - } -} - -/// Convenience macro to log a message with an `Rc>` +/// Convenience macro to log a message with an `Option>>` #[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); + ($log_collector:expr, $message:expr) => { + if let Some(log_collector) = $log_collector.as_ref() { + if let Ok(log_collector) = log_collector.try_borrow_mut() { + log_collector.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)*)); + ($log_collector:expr, $fmt:expr, $($arg:tt)*) => { + if let Some(log_collector) = $log_collector.as_ref() { + if let Ok(log_collector) = log_collector.try_borrow_mut() { + log_collector.log(&format!($fmt, $($arg)*)); } } }; @@ -85,10 +64,10 @@ macro_rules! ic_logger_msg { #[macro_export] macro_rules! ic_msg { ($invoke_context:expr, $message:expr) => { - $crate::ic_logger_msg!($invoke_context.get_logger(), $message) + $crate::ic_logger_msg!($invoke_context.get_log_collector(), $message) }; ($invoke_context:expr, $fmt:expr, $($arg:tt)*) => { - $crate::ic_logger_msg!($invoke_context.get_logger(), $fmt, $($arg)*) + $crate::ic_logger_msg!($invoke_context.get_log_collector(), $fmt, $($arg)*) }; } diff --git a/program-runtime/src/stable_log.rs b/program-runtime/src/stable_log.rs index 47fedfaf3f7f0e..bd484d555a0275 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, log_collector::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, invoke_ /// ``` /// /// 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, data: & /// ```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 @@ -85,6 +98,10 @@ pub fn program_success(logger: &Rc>, program_id: &Pubkey) { /// ```notrust /// "Program
failed: " /// ``` -pub fn program_failure(logger: &Rc>, program_id: &Pubkey, err: &InstructionError) { - ic_logger_msg!(logger, "Program {} failed: {}", program_id, err); +pub fn program_failure( + log_collector: &Option>>, + program_id: &Pubkey, + err: &InstructionError, +) { + 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 600dc0476a453b..2c6d571554cf8a 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 ab623d02abdb21..f88647b10cde5d 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -18,7 +18,7 @@ use solana_program_runtime::{ ic_logger_msg, ic_msg, instruction_processor::{Executor, InstructionProcessor}, invoke_context::{ComputeMeter, InvokeContext}, - log_collector::Logger, + log_collector::LogCollector, stable_log, }; use solana_rbpf::{ @@ -210,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()?; @@ -226,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) @@ -239,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); } @@ -249,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!( @@ -259,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 { @@ -309,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) } } @@ -321,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()?; @@ -330,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); } @@ -346,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( @@ -389,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); } @@ -407,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); } @@ -427,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); } @@ -444,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); } @@ -518,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)?; @@ -537,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 { @@ -553,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); } @@ -567,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); } @@ -587,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 { @@ -607,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); } @@ -663,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)?; @@ -677,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 { @@ -701,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 { @@ -718,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); } @@ -742,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() ); @@ -756,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: _, @@ -769,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); } @@ -783,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); @@ -798,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); } } @@ -825,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); } @@ -940,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"); @@ -969,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 { @@ -986,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, @@ -1002,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); } } @@ -1018,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); } } @@ -1045,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 3aa33414dd7fb2..d05ba9732a4377 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -1,10 +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}, - log_collector::Logger, + log_collector::LogCollector, stable_log, }; use solana_rbpf::{ @@ -230,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, @@ -239,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, )?; @@ -248,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, )?; @@ -257,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, @@ -609,7 +609,7 @@ impl<'a> SyscallObject for SyscallPanic<'a> { /// Log a user's info message pub struct SyscallLog<'a> { compute_meter: Rc>, - logger: Rc>, + log_collector: Option>>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLog<'a> { @@ -631,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) }, ), @@ -645,7 +645,7 @@ impl<'a> SyscallObject for SyscallLog<'a> { pub struct SyscallLogU64 { cost: u64, compute_meter: Rc>, - logger: Rc>, + log_collector: Option>>, } impl SyscallObject for SyscallLogU64 { fn call( @@ -660,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 @@ -674,7 +674,7 @@ impl SyscallObject for SyscallLogU64 { pub struct SyscallLogBpfComputeUnits { cost: u64, compute_meter: Rc>, - logger: Rc>, + log_collector: Option>>, } impl SyscallObject for SyscallLogBpfComputeUnits { fn call( @@ -688,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); } } @@ -708,7 +701,7 @@ impl SyscallObject for SyscallLogBpfComputeUnits { pub struct SyscallLogPubkey<'a> { cost: u64, compute_meter: Rc>, - logger: Rc>, + log_collector: Option>>, loader_id: &'a Pubkey, } impl<'a> SyscallObject for SyscallLogPubkey<'a> { @@ -727,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); } } @@ -2430,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); } @@ -2443,7 +2436,7 @@ mod tests { use super::*; use solana_program_runtime::{ invoke_context::{ComputeMeter, ThisInvokeContext}, - log_collector::{LogCollector, Logger}, + log_collector::LogCollector, }; use solana_rbpf::{ ebpf::HOST_ALIGN, memory_region::MemoryRegion, user_error::UserError, vm::Config, @@ -2836,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: ComputeMeter::new_ref(string.len() as u64), - logger: Logger::new_ref(Some(log.clone())), + log_collector: Some(log.clone()), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2858,7 +2851,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); @@ -2866,7 +2859,7 @@ mod tests { let mut syscall_sol_log = SyscallLog { compute_meter: ComputeMeter::new_ref(string.len() as u64 * 3), - logger: Logger::new_ref(None), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2904,7 +2897,7 @@ mod tests { let mut syscall_sol_log = SyscallLog { compute_meter: ComputeMeter::new_ref((string.len() as u64 * 2) - 1), - logger: Logger::new_ref(None), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2938,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: ComputeMeter::new_ref(std::u64::MAX), - logger: Logger::new_ref(Some(log.clone())), + log_collector: Some(log.clone()), }; let config = Config::default(); let memory_mapping = MemoryMapping::new::(vec![], &config).unwrap(); @@ -2954,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); @@ -2980,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: ComputeMeter::new_ref(1), - logger: Logger::new_ref(Some(log.clone())), + log_collector: Some(log.clone()), loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); @@ -2995,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); @@ -3007,7 +3000,7 @@ mod tests { let mut syscall_sol_pubkey = SyscallLogPubkey { cost: 1, compute_meter: ComputeMeter::new_ref(1), - logger: Logger::new_ref(None), + log_collector: None, loader_id: &bpf_loader::id(), }; let mut result: Result> = Ok(0); diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index a9569a13db1ed1..33e7468e42da7b 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -3681,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, @@ -3860,7 +3842,7 @@ impl Bank { }; let log_collector = if enable_log_recording { - Some(Rc::new(LogCollector::default())) + Some(LogCollector::new_ref()) } else { None }; @@ -3901,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 a32b7122f8e598..b5a38edb863223 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 3dfca07f028ba1..02a8425c7db901 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -45,7 +45,7 @@ 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, From d329f4e06e19530f363b19413d67a983bec48888 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Mon, 22 Nov 2021 21:50:02 +0100 Subject: [PATCH 5/6] Removes inner RefCell from LogCollector. --- program-runtime/src/log_collector.rs | 35 +++++++++++----------------- 1 file changed, 14 insertions(+), 21 deletions(-) diff --git a/program-runtime/src/log_collector.rs b/program-runtime/src/log_collector.rs index a5c0e7548fe37c..340763b5f386c0 100644 --- a/program-runtime/src/log_collector.rs +++ b/program-runtime/src/log_collector.rs @@ -3,41 +3,34 @@ 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 { - inner: RefCell::new(LogCollectorInner::default()), - })) + 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 } } @@ -46,14 +39,14 @@ impl From for Vec { macro_rules! ic_logger_msg { ($log_collector:expr, $message:expr) => { if let Some(log_collector) = $log_collector.as_ref() { - if let Ok(log_collector) = log_collector.try_borrow_mut() { + if let Ok(mut log_collector) = log_collector.try_borrow_mut() { log_collector.log($message); } } }; ($log_collector:expr, $fmt:expr, $($arg:tt)*) => { if let Some(log_collector) = $log_collector.as_ref() { - if let Ok(log_collector) = log_collector.try_borrow_mut() { + if let Ok(mut log_collector) = log_collector.try_borrow_mut() { log_collector.log(&format!($fmt, $($arg)*)); } } @@ -77,7 +70,7 @@ pub(crate) mod tests { #[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"); From 81e3c2dec834f2655833f5c60be746e65b40bbaa Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alexander=20Mei=C3=9Fner?= Date: Tue, 23 Nov 2021 10:51:38 +0100 Subject: [PATCH 6/6] Adds the log::debug!() message to ic_logger_msg!() again. --- program-runtime/src/log_collector.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/program-runtime/src/log_collector.rs b/program-runtime/src/log_collector.rs index 340763b5f386c0..f5eaea48e1e501 100644 --- a/program-runtime/src/log_collector.rs +++ b/program-runtime/src/log_collector.rs @@ -1,3 +1,4 @@ +pub use log; use std::{cell::RefCell, rc::Rc}; const LOG_MESSAGES_BYTES_LIMIT: usize = 10 * 1000; @@ -38,6 +39,7 @@ impl From for Vec { #[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); @@ -45,6 +47,7 @@ macro_rules! ic_logger_msg { } }; ($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)*));