diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index ce1302942a..0cb735581a 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -27,6 +27,7 @@ use solana_sdk::{ clock::Clock, entrypoint::SUCCESS, feature_set::{bpf_compute_budget_balancing, prevent_upgrade_and_invoke}, + ic_logger_msg, ic_msg, instruction::InstructionError, keyed_account::{from_keyed_account, next_keyed_account, KeyedAccount}, loader_instruction::LoaderInstruction, @@ -56,30 +57,11 @@ pub enum BPFError { } impl UserDefinedError for BPFError {} -/// Point all log messages to the log collector -macro_rules! log { - ($logger:ident, $message:expr) => { - if let Ok(logger) = $logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log($message); - } - } - }; - ($logger:ident, $fmt:expr, $($arg:tt)*) => { - if let Ok(logger) = $logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!($fmt, $($arg)*)); - } - } - }; -} - fn map_ebpf_error( invoke_context: &mut dyn InvokeContext, e: EbpfError, ) -> InstructionError { - let logger = invoke_context.get_logger(); - log!(logger, "{}", e); + ic_msg!(invoke_context, "{}", e); InstructionError::InvalidAccountData } @@ -89,8 +71,6 @@ pub fn create_and_cache_executor( invoke_context: &mut dyn InvokeContext, use_jit: bool, ) -> Result, InstructionError> { - let logger = invoke_context.get_logger(); - let bpf_compute_budget = invoke_context.get_bpf_compute_budget(); let mut program = Executable::::from_elf( data, @@ -112,13 +92,13 @@ pub fn create_and_cache_executor( ) .map_err(|e| map_ebpf_error(invoke_context, EbpfError::UserError(e)))?; let syscall_registry = syscalls::register_syscalls(invoke_context).map_err(|e| { - log!(logger, "Failed to register syscalls: {}", e); + ic_msg!(invoke_context, "Failed to register syscalls: {}", e); InstructionError::ProgramEnvironmentSetupFailure })?; program.set_syscall_registry(syscall_registry); if use_jit { if let Err(err) = program.jit_compile() { - log!(logger, "Failed to compile program {:?}", err); + ic_msg!(invoke_context, "Failed to compile program {:?}", err); return Err(InstructionError::ProgramFailedToCompile); } } @@ -133,11 +113,14 @@ fn write_program_data( bytes: &[u8], invoke_context: &mut dyn InvokeContext, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); - let len = bytes.len(); if data.len() < offset + len { - log!(logger, "Write overflow: {} < {}", data.len(), offset + len); + ic_msg!( + invoke_context, + "Write overflow: {} < {}", + data.len(), + offset + len + ); return Err(InstructionError::AccountDataTooSmall); } data[offset..offset + len].copy_from_slice(&bytes); @@ -218,7 +201,7 @@ fn process_instruction_common( let first_account = next_keyed_account(account_iter)?; if first_account.executable()? { if first_account.unsigned_key() != program_id { - log!(logger, "Program id mismatch"); + ic_logger_msg!(logger, "Program id mismatch"); return Err(InstructionError::IncorrectProgramId); } @@ -230,7 +213,10 @@ fn process_instruction_common( { let programdata = next_keyed_account(account_iter)?; if programdata_address != *programdata.unsigned_key() { - log!(logger, "Wrong ProgramData account for this Program account"); + ic_logger_msg!( + logger, + "Wrong ProgramData account for this Program account" + ); return Err(InstructionError::InvalidArgument); } ( @@ -239,7 +225,7 @@ fn process_instruction_common( UpgradeableLoaderState::programdata_data_offset()?, ) } else { - log!(logger, "Invalid Program account"); + ic_logger_msg!(logger, "Invalid Program account"); return Err(InstructionError::InvalidAccountData); } } else { @@ -249,7 +235,7 @@ fn process_instruction_common( let loader_id = &program.owner()?; if !check_loader_id(loader_id) { - log!(logger, "Executable account not owned by the BPF loader"); + ic_logger_msg!(logger, "Executable account not owned by the BPF loader"); return Err(InstructionError::IncorrectProgramId); } @@ -272,7 +258,7 @@ fn process_instruction_common( )? } else { if !check_loader_id(program_id) { - log!(logger, "Invalid BPF loader id"); + ic_logger_msg!(logger, "Invalid BPF loader id"); return Err(InstructionError::IncorrectProgramId); } @@ -315,7 +301,7 @@ fn process_loader_upgradeable_instruction( .map(|account| account.unsigned_key()); if UpgradeableLoaderState::Uninitialized != buffer.state()? { - log!(logger, "Buffer account already initialized"); + ic_logger_msg!(logger, "Buffer account already initialized"); return Err(InstructionError::AccountAlreadyInitialized); } buffer.set_state(&UpgradeableLoaderState::Buffer { @@ -328,19 +314,19 @@ fn process_loader_upgradeable_instruction( if let UpgradeableLoaderState::Buffer { authority_address } = buffer.state()? { if authority_address == None { - log!(logger, "Buffer is immutable"); + ic_logger_msg!(logger, "Buffer is immutable"); return Err(InstructionError::Immutable); // TODO better error code } if authority_address != Some(*authority.unsigned_key()) { - log!(logger, "Incorrect buffer authority provided"); + ic_logger_msg!(logger, "Incorrect buffer authority provided"); return Err(InstructionError::IncorrectAuthority); } if authority.signer_key().is_none() { - log!(logger, "Buffer authority did not sign"); + ic_logger_msg!(logger, "Buffer authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - log!(logger, "Invalid Buffer account"); + ic_logger_msg!(logger, "Invalid Buffer account"); return Err(InstructionError::InvalidAccountData); } write_program_data( @@ -365,15 +351,15 @@ fn process_loader_upgradeable_instruction( // Verify Program account if UpgradeableLoaderState::Uninitialized != program.state()? { - log!(logger, "Program account already initialized"); + ic_logger_msg!(logger, "Program account already initialized"); return Err(InstructionError::AccountAlreadyInitialized); } if program.data_len()? < UpgradeableLoaderState::program_len()? { - log!(logger, "Program account too small"); + ic_logger_msg!(logger, "Program account too small"); return Err(InstructionError::AccountDataTooSmall); } if program.lamports()? < rent.minimum_balance(program.data_len()?) { - log!(logger, "Program account not rent-exempt"); + ic_logger_msg!(logger, "Program account not rent-exempt"); return Err(InstructionError::ExecutableAccountNotRentExempt); } @@ -384,7 +370,7 @@ fn process_loader_upgradeable_instruction( } = buffer.state()? { } else { - log!(logger, "Invalid Buffer account"); + ic_logger_msg!(logger, "Invalid Buffer account"); return Err(InstructionError::InvalidArgument); } @@ -395,11 +381,11 @@ fn process_loader_upgradeable_instruction( if buffer.data_len()? < UpgradeableLoaderState::buffer_data_offset()? || buffer_data_len == 0 { - log!(logger, "Buffer account too small"); + ic_logger_msg!(logger, "Buffer account too small"); return Err(InstructionError::InvalidAccountData); } if max_data_len < buffer_data_len { - log!(logger, "Max data length is too small to hold Buffer data"); + ic_logger_msg!(logger, "Max data length is too small to hold Buffer data"); return Err(InstructionError::AccountDataTooSmall); } @@ -408,7 +394,7 @@ fn process_loader_upgradeable_instruction( let (derived_address, bump_seed) = Pubkey::find_program_address(&[program.unsigned_key().as_ref()], &program_id); if derived_address != *programdata.unsigned_key() { - log!(logger, "ProgramData address is not derived"); + ic_logger_msg!(logger, "ProgramData address is not derived"); return Err(InstructionError::InvalidArgument); } @@ -459,7 +445,7 @@ fn process_loader_upgradeable_instruction( payer.try_account_ref_mut()?.lamports += buffer.lamports()?; buffer.try_account_ref_mut()?.lamports = 0; - log!(logger, "Deployed program {:?}", program.unsigned_key()); + ic_logger_msg!(logger, "Deployed program {:?}", program.unsigned_key()); } UpgradeableLoaderInstruction::Upgrade => { let programdata = next_keyed_account(account_iter)?; @@ -473,17 +459,17 @@ fn process_loader_upgradeable_instruction( // Verify Program account if !program.executable()? { - log!(logger, "Program account not executable"); + ic_logger_msg!(logger, "Program account not executable"); return Err(InstructionError::AccountNotExecutable); } if !program.is_writable() && invoke_context.is_feature_active(&prevent_upgrade_and_invoke::id()) { - log!(logger, "Program account not writeable"); + ic_logger_msg!(logger, "Program account not writeable"); return Err(InstructionError::InvalidArgument); } if &program.owner()? != program_id { - log!(logger, "Program account not owned by loader"); + ic_logger_msg!(logger, "Program account not owned by loader"); return Err(InstructionError::IncorrectProgramId); } if let UpgradeableLoaderState::Program { @@ -491,11 +477,11 @@ fn process_loader_upgradeable_instruction( } = program.state()? { if programdata_address != *programdata.unsigned_key() { - log!(logger, "Program and ProgramData account mismatch"); + ic_logger_msg!(logger, "Program and ProgramData account mismatch"); return Err(InstructionError::InvalidArgument); } } else { - log!(logger, "Invalid Program account"); + ic_logger_msg!(logger, "Invalid Program account"); return Err(InstructionError::InvalidAccountData); } @@ -506,7 +492,7 @@ fn process_loader_upgradeable_instruction( } = buffer.state()? { } else { - log!(logger, "Invalid Buffer account"); + ic_logger_msg!(logger, "Invalid Buffer account"); return Err(InstructionError::InvalidArgument); } @@ -518,18 +504,18 @@ fn process_loader_upgradeable_instruction( if buffer.data_len()? < UpgradeableLoaderState::buffer_data_offset()? || buffer_data_len == 0 { - log!(logger, "Buffer account too small"); + ic_logger_msg!(logger, "Buffer account too small"); return Err(InstructionError::InvalidAccountData); } // Verify ProgramData account if programdata.data_len()? < UpgradeableLoaderState::programdata_len(buffer_data_len)? { - log!(logger, "ProgramData account not large enough"); + ic_logger_msg!(logger, "ProgramData account not large enough"); return Err(InstructionError::AccountDataTooSmall); } if programdata.lamports()? + buffer.lamports()? < programdata_balance_required { - log!(logger, "Buffer account balance too low to fund upgrade"); + ic_logger_msg!(logger, "Buffer account balance too low to fund upgrade"); return Err(InstructionError::InsufficientFunds); } if let UpgradeableLoaderState::ProgramData { @@ -538,19 +524,19 @@ fn process_loader_upgradeable_instruction( } = programdata.state()? { if upgrade_authority_address == None { - log!(logger, "Program not upgradeable"); + ic_logger_msg!(logger, "Program not upgradeable"); return Err(InstructionError::Immutable); } if upgrade_authority_address != Some(*authority.unsigned_key()) { - log!(logger, "Incorrect upgrade authority provided"); + ic_logger_msg!(logger, "Incorrect upgrade authority provided"); return Err(InstructionError::IncorrectAuthority); } if authority.signer_key().is_none() { - log!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(logger, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } } else { - log!(logger, "Invalid ProgramData account"); + ic_logger_msg!(logger, "Invalid ProgramData account"); return Err(InstructionError::InvalidAccountData); } @@ -587,7 +573,7 @@ fn process_loader_upgradeable_instruction( buffer.try_account_ref_mut()?.lamports = 0; programdata.try_account_ref_mut()?.lamports = programdata_balance_required; - log!(logger, "Upgraded program {:?}", program.unsigned_key()); + ic_logger_msg!(logger, "Upgraded program {:?}", program.unsigned_key()); } UpgradeableLoaderInstruction::SetAuthority => { let account = next_keyed_account(account_iter)?; @@ -599,15 +585,15 @@ fn process_loader_upgradeable_instruction( match account.state()? { UpgradeableLoaderState::Buffer { authority_address } => { if authority_address == None { - log!(logger, "Buffer is immutable"); + ic_logger_msg!(logger, "Buffer is immutable"); return Err(InstructionError::Immutable); } if authority_address != Some(*present_authority.unsigned_key()) { - log!(logger, "Incorrect buffer authority provided"); + ic_logger_msg!(logger, "Incorrect buffer authority provided"); return Err(InstructionError::IncorrectAuthority); } if present_authority.signer_key().is_none() { - log!(logger, "Buffer authority did not sign"); + ic_logger_msg!(logger, "Buffer authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } account.set_state(&UpgradeableLoaderState::Buffer { @@ -619,15 +605,15 @@ fn process_loader_upgradeable_instruction( upgrade_authority_address, } => { if upgrade_authority_address == None { - log!(logger, "Program not upgradeable"); + ic_logger_msg!(logger, "Program not upgradeable"); return Err(InstructionError::Immutable); } if upgrade_authority_address != Some(*present_authority.unsigned_key()) { - log!(logger, "Incorrect upgrade authority provided"); + ic_logger_msg!(logger, "Incorrect upgrade authority provided"); return Err(InstructionError::IncorrectAuthority); } if present_authority.signer_key().is_none() { - log!(logger, "Upgrade authority did not sign"); + ic_logger_msg!(logger, "Upgrade authority did not sign"); return Err(InstructionError::MissingRequiredSignature); } account.set_state(&UpgradeableLoaderState::ProgramData { @@ -636,12 +622,12 @@ fn process_loader_upgradeable_instruction( })?; } _ => { - log!(logger, "Account does not support authorities"); + ic_logger_msg!(logger, "Account does not support authorities"); return Err(InstructionError::InvalidAccountData); } } - log!(logger, "New authority {:?}", new_authority); + ic_logger_msg!(logger, "New authority {:?}", new_authority); } } @@ -655,18 +641,20 @@ fn process_loader_instruction( invoke_context: &mut dyn InvokeContext, use_jit: bool, ) -> Result<(), InstructionError> { - let logger = invoke_context.get_logger(); let account_iter = &mut keyed_accounts.iter(); let program = next_keyed_account(account_iter)?; if program.owner()? != *program_id { - log!(logger, "Executable account not owned by the BPF loader"); + ic_msg!( + invoke_context, + "Executable account not owned by the BPF loader" + ); return Err(InstructionError::IncorrectProgramId); } match limited_deserialize(instruction_data)? { LoaderInstruction::Write { offset, bytes } => { if program.signer_key().is_none() { - log!(logger, "Program account did not sign"); + ic_msg!(invoke_context, "Program account did not sign"); return Err(InstructionError::MissingRequiredSignature); } write_program_data( @@ -678,7 +666,7 @@ fn process_loader_instruction( } LoaderInstruction::Finalize => { if program.signer_key().is_none() { - log!(logger, "key[0] did not sign the transaction"); + ic_msg!(invoke_context, "key[0] did not sign the transaction"); return Err(InstructionError::MissingRequiredSignature); } @@ -689,7 +677,11 @@ fn process_loader_instruction( use_jit, )?; program.try_account_ref_mut()?.executable = true; - log!(logger, "Finalized account {:?}", program.unsigned_key()); + ic_msg!( + invoke_context, + "Finalized account {:?}", + program.unsigned_key() + ); } } @@ -757,7 +749,7 @@ impl Executor for BPFExecutor { ) { Ok(info) => info, Err(e) => { - log!(logger, "Failed to create BPF VM: {}", e); + ic_logger_msg!(logger, "Failed to create BPF VM: {}", e); return Err(InstructionError::ProgramEnvironmentSetupFailure); } }; @@ -771,7 +763,7 @@ impl Executor for BPFExecutor { vm.execute_program_interpreted(&mut instruction_meter) }; let after = compute_meter.borrow().get_remaining(); - log!( + ic_logger_msg!( logger, "Program {} consumed {} of {} compute units", program_id, @@ -787,13 +779,13 @@ impl Executor for BPFExecutor { } } Err(error) => { - log!(logger, "Program {} BPF VM error: {}", program_id, error); + ic_logger_msg!(logger, "Program {} BPF VM error: {}", program_id, error); let error = match error { EbpfError::UserError(BPFError::SyscallError( SyscallError::InstructionError(error), )) => error, err => { - log!(logger, "Program failed to complete: {:?}", err); + ic_logger_msg!(logger, "Program failed to complete: {:?}", err); InstructionError::ProgramFailedToComplete } }; diff --git a/sdk/src/process_instruction.rs b/sdk/src/process_instruction.rs index cd910d61f4..454fc3758c 100644 --- a/sdk/src/process_instruction.rs +++ b/sdk/src/process_instruction.rs @@ -65,6 +65,36 @@ pub trait InvokeContext { fn get_account(&self, pubkey: &Pubkey) -> Option>; } +/// 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)*) + }; +} + #[derive(Clone, Copy, Debug, AbiExample)] pub struct BpfComputeBudget { /// Number of compute units that an instruction is allowed. Compute units @@ -194,11 +224,7 @@ pub mod stable_log { program_id: &Pubkey, invoke_depth: usize, ) { - if let Ok(logger) = logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!("Program {} invoke [{}]", program_id, invoke_depth)); - } - } + ic_logger_msg!(logger, "Program {} invoke [{}]", program_id, invoke_depth); } /// Log a message from the program itself. @@ -207,11 +233,7 @@ pub mod stable_log { /// "Program log: " /// That is, any program-generated output is guaranteed to be prefixed by "Program log: " pub fn program_log(logger: &Rc>, message: &str) { - if let Ok(logger) = logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!("Program log: {}", message)) - } - } + ic_logger_msg!(logger, "Program log: {}", message); } /// Log successful program execution. @@ -219,11 +241,7 @@ pub mod stable_log { /// The general form is: /// "Program
success" pub fn program_success(logger: &Rc>, program_id: &Pubkey) { - if let Ok(logger) = logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!("Program {} success", program_id)); - } - } + ic_logger_msg!(logger, "Program {} success", program_id); } /// Log program execution failure @@ -235,11 +253,7 @@ pub mod stable_log { program_id: &Pubkey, err: &InstructionError, ) { - if let Ok(logger) = logger.try_borrow_mut() { - if logger.log_enabled() { - logger.log(&format!("Program {} failed: {}", program_id, err)); - } - } + ic_logger_msg!(logger, "Program {} failed: {}", program_id, err); } }