From 0b1015f7d32856f94a142c5a6a62b0acfc9f19e2 Mon Sep 17 00:00:00 2001 From: Jack May Date: Thu, 28 Jan 2021 10:04:54 -0800 Subject: [PATCH] Richer runtime failure logging (#14875) --- programs/bpf/tests/programs.rs | 4 +- programs/bpf_loader/src/lib.rs | 4 +- programs/bpf_loader/src/syscalls.rs | 191 ++++++++++++++++----------- runtime/src/message_processor.rs | 194 +++++++++++++++++++--------- 4 files changed, 246 insertions(+), 147 deletions(-) diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index 82a225096d..974bb8b8b3 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -916,13 +916,13 @@ fn test_program_bpf_invoke_sanity() { do_invoke_failure_test_local( TEST_INSTRUCTION_DATA_TOO_LARGE, - TransactionError::InstructionError(0, InstructionError::ComputationalBudgetExceeded), + TransactionError::InstructionError(0, InstructionError::ProgramFailedToComplete), &[], ); do_invoke_failure_test_local( TEST_INSTRUCTION_META_TOO_LARGE, - TransactionError::InstructionError(0, InstructionError::ComputationalBudgetExceeded), + TransactionError::InstructionError(0, InstructionError::ProgramFailedToComplete), &[], ); diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 0cb735581a..bd6d7f74a6 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -779,17 +779,15 @@ impl Executor for BPFExecutor { } } Err(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 => { - ic_logger_msg!(logger, "Program failed to complete: {:?}", err); + ic_logger_msg!(logger, "Program failed to complete: {}", err); InstructionError::ProgramFailedToComplete } }; - stable_log::program_failure(&logger, program_id, &error); return Err(error); } diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 7b073a3112..d5e6755e48 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -23,6 +23,7 @@ use solana_sdk::{ use_loaded_program_accounts, }, hash::{Hasher, HASH_BYTES}, + ic_msg, instruction::{AccountMeta, Instruction, InstructionError}, keyed_account::KeyedAccount, native_loader, @@ -59,14 +60,18 @@ pub enum SyscallError { MalformedSignerSeed(Utf8Error, Vec), #[error("Could not create program address with signer seeds: {0}")] BadSeeds(PubkeyError), - #[error("Program id is not supported by cross-program invocations")] - ProgramNotSupported, + #[error("Program {0} supported by inner instructions")] + ProgramNotSupported(Pubkey), #[error("{0}")] InstructionError(InstructionError), #[error("Unaligned pointer")] UnalignedPointer, #[error("Too many signers")] TooManySigners, + #[error("Instruction passed to inner instruction is too large")] + InstructionTooLarge, + #[error("Too many accounts passed to inner instruction")] + TooManyAccounts, } impl From for EbpfError { fn from(error: SyscallError) -> Self { @@ -898,10 +903,7 @@ impl<'a> SyscallInvokeSigned<'a> for SyscallInvokeSignedRust<'a> { check_instruction_size( ix.accounts.len(), ix.data.len(), - self.invoke_context - .borrow() - .get_bpf_compute_budget() - .max_cpi_instruction_size, + &self.invoke_context.borrow(), )?; let accounts = translate_slice::( @@ -1186,10 +1188,7 @@ impl<'a> SyscallInvokeSigned<'a> for SyscallInvokeSignedC<'a> { check_instruction_size( ix_c.accounts_len, ix_c.data_len, - self.invoke_context - .borrow() - .get_bpf_compute_budget() - .max_cpi_instruction_size, + &self.invoke_context.borrow(), )?; let program_id = translate_type::(memory_mapping, ix_c.program_id_addr, self.loader_id)?; @@ -1408,12 +1407,14 @@ where let mut accounts = Vec::with_capacity(account_keys.len()); let mut refs = Vec::with_capacity(account_keys.len()); for (i, ref account_key) in account_keys.iter().enumerate() { - let account = - invoke_context - .get_account(&account_key) - .ok_or(SyscallError::InstructionError( - InstructionError::MissingAccount, - ))?; + let account = invoke_context.get_account(&account_key).ok_or_else(|| { + ic_msg!( + invoke_context, + "Instruction references an unknown account {:?}", + account_key + ); + SyscallError::InstructionError(InstructionError::MissingAccount) + })?; if (invoke_context.is_feature_active(&use_loaded_program_accounts::id()) && i == program_account_index) @@ -1439,6 +1440,11 @@ where accounts.push(account); refs.push(account_ref); } else { + ic_msg!( + invoke_context, + "Instruction references an unknown account {:?}", + account_key + ); return Err(SyscallError::InstructionError(InstructionError::MissingAccount).into()); } } @@ -1449,12 +1455,14 @@ where fn check_instruction_size( num_accounts: usize, data_len: usize, - max_size: usize, + invoke_context: &Ref<&mut dyn InvokeContext>, ) -> Result<(), EbpfError> { - if max_size < num_accounts * size_of::() + data_len { - return Err( - SyscallError::InstructionError(InstructionError::ComputationalBudgetExceeded).into(), - ); + if invoke_context + .get_bpf_compute_budget() + .max_cpi_instruction_size + < num_accounts * size_of::() + data_len + { + return Err(SyscallError::InstructionTooLarge.into()); } Ok(()) } @@ -1471,9 +1479,7 @@ fn check_account_infos( { // Cap the number of account_infos a caller can pass to approximate // maximum that accounts that could be passed in an instruction - return Err( - SyscallError::InstructionError(InstructionError::ComputationalBudgetExceeded).into(), - ); + return Err(SyscallError::TooManyAccounts.into()); }; Ok(()) } @@ -1488,30 +1494,40 @@ fn check_authorized_program( || (bpf_loader_upgradeable::check_id(program_id) && !bpf_loader_upgradeable::is_upgrade_instruction(instruction_data)) { - return Err(SyscallError::InstructionError(InstructionError::UnsupportedProgramId).into()); + return Err(SyscallError::ProgramNotSupported(*program_id).into()); } Ok(()) } fn get_upgradeable_executable( + callee_program_id: &Pubkey, program_account: &RefCell, invoke_context: &Ref<&mut dyn InvokeContext>, ) -> Result)>, EbpfError> { if program_account.borrow().owner == bpf_loader_upgradeable::id() { - if let UpgradeableLoaderState::Program { - programdata_address, - } = program_account - .borrow() - .state() - .map_err(SyscallError::InstructionError)? - { - if let Some(account) = invoke_context.get_account(&programdata_address) { - Ok(Some((programdata_address, account))) - } else { - Err(SyscallError::InstructionError(InstructionError::MissingAccount).into()) + match program_account.borrow().state() { + Ok(UpgradeableLoaderState::Program { + programdata_address, + }) => { + if let Some(account) = invoke_context.get_account(&programdata_address) { + Ok(Some((programdata_address, account))) + } else { + ic_msg!( + invoke_context, + "Unknown upgradeable programdata account {:?}", + programdata_address, + ); + Err(SyscallError::InstructionError(InstructionError::MissingAccount).into()) + } + } + _ => { + ic_msg!( + invoke_context, + "Invalid upgradeable program account {:?}", + callee_program_id, + ); + Err(SyscallError::InstructionError(InstructionError::InvalidAccountData).into()) } - } else { - Err(SyscallError::InstructionError(InstructionError::MissingAccount).into()) } } else { Ok(None) @@ -1560,8 +1576,13 @@ fn call<'a>( .iter() .collect::>(); let (message, callee_program_id, callee_program_id_index) = - MessageProcessor::create_message(&instruction, &keyed_account_refs, &signers) - .map_err(SyscallError::InstructionError)?; + MessageProcessor::create_message( + &instruction, + &keyed_account_refs, + &signers, + &invoke_context, + ) + .map_err(SyscallError::InstructionError)?; let caller_privileges = message .account_keys .iter() @@ -1589,14 +1610,13 @@ fn call<'a>( // Construct executables - let program_account = - (**accounts - .get(callee_program_id_index) - .ok_or(SyscallError::InstructionError( - InstructionError::MissingAccount, - ))?) - .clone(); - let programdata_executable = get_upgradeable_executable(&program_account, &invoke_context)?; + let program_account = (**accounts.get(callee_program_id_index).ok_or_else(|| { + ic_msg!(invoke_context, "Unknown program {:?}", callee_program_id,); + SyscallError::InstructionError(InstructionError::MissingAccount) + })?) + .clone(); + let programdata_executable = + get_upgradeable_executable(&callee_program_id, &program_account, &invoke_context)?; let mut executables = vec![(callee_program_id, program_account)]; if let Some(executable) = programdata_executable { executables.push(executable); @@ -1640,39 +1660,52 @@ fn call<'a>( } // Copy results back to caller - for (i, (account, account_ref)) in accounts.iter().zip(account_refs).enumerate() { - let account = account.borrow(); - if let Some(account_ref) = account_ref { - if message.is_writable(i) && !account.executable { - *account_ref.lamports = account.lamports; - *account_ref.owner = account.owner; - if account_ref.data.len() != account.data.len() { - if !account_ref.data.is_empty() { - // Only support for `CreateAccount` at this time. - // Need a way to limit total realloc size across multiple CPI calls - return Err(SyscallError::InstructionError( - InstructionError::InvalidRealloc, - ) - .into()); + { + let invoke_context = syscall.get_context()?; + for (i, (account, account_ref)) in accounts.iter().zip(account_refs).enumerate() { + let account = account.borrow(); + if let Some(account_ref) = account_ref { + if message.is_writable(i) && !account.executable { + *account_ref.lamports = account.lamports; + *account_ref.owner = account.owner; + if account_ref.data.len() != account.data.len() { + if !account_ref.data.is_empty() { + // Only support for `CreateAccount` at this time. + // Need a way to limit total realloc size across multiple CPI calls + ic_msg!( + invoke_context, + "Inner instructions do not support realloc, only SystemProgram::CreateAccount", + ); + return Err(SyscallError::InstructionError( + InstructionError::InvalidRealloc, + ) + .into()); + } + if account.data.len() > account_ref.data.len() + MAX_PERMITTED_DATA_INCREASE + { + ic_msg!( + invoke_context, + "SystemProgram::CreateAccount data size limited to {:?} in inner instructions", + MAX_PERMITTED_DATA_INCREASE + ); + return Err(SyscallError::InstructionError( + InstructionError::InvalidRealloc, + ) + .into()); + } + let _ = translate( + memory_mapping, + AccessType::Store, + account_ref.vm_data_addr, + account.data.len() as u64, + )?; + *account_ref.ref_to_len_in_vm = account.data.len() as u64; + *account_ref.serialized_len_ptr = account.data.len() as u64; } - if account.data.len() > account_ref.data.len() + MAX_PERMITTED_DATA_INCREASE { - return Err(SyscallError::InstructionError( - InstructionError::InvalidRealloc, - ) - .into()); - } - let _ = translate( - memory_mapping, - AccessType::Store, - account_ref.vm_data_addr, - account.data.len() as u64, - )?; - *account_ref.ref_to_len_in_vm = account.data.len() as u64; - *account_ref.serialized_len_ptr = account.data.len() as u64; + account_ref + .data + .clone_from_slice(&account.data[0..account_ref.data.len()]); } - account_ref - .data - .clone_from_slice(&account.data[0..account_ref.data.len()]); } } } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index a661bba47b..d7504fccbb 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -9,6 +9,7 @@ use solana_sdk::{ account_utils::StateMut, bpf_loader_upgradeable::{self, UpgradeableLoaderState}, feature_set::{instructions_sysvar_enabled, track_writable_deescalation, FeatureSet}, + ic_msg, instruction::{CompiledInstruction, Instruction, InstructionError}, keyed_account::{create_keyed_readonly_accounts, KeyedAccount}, message::Message, @@ -22,7 +23,12 @@ use solana_sdk::{ system_program, transaction::TransactionError, }; -use std::{cell::RefCell, collections::HashMap, rc::Rc, sync::Arc}; +use std::{ + cell::{Ref, RefCell}, + collections::HashMap, + rc::Rc, + sync::Arc, +}; pub struct Executors { pub executors: HashMap>, @@ -525,6 +531,7 @@ impl MessageProcessor { instruction: &Instruction, keyed_accounts: &[&KeyedAccount], signers: &[Pubkey], + invoke_context: &Ref<&mut dyn InvokeContext>, ) -> Result<(Message, Pubkey, usize), InstructionError> { // Check for privilege escalation for account in instruction.accounts.iter() { @@ -537,9 +544,21 @@ impl MessageProcessor { None } }) - .ok_or(InstructionError::MissingAccount)?; + .ok_or_else(|| { + ic_msg!( + invoke_context, + "Instruction references an unknown account {:?}", + account.pubkey + ); + InstructionError::MissingAccount + })?; // Readonly account cannot become writable if account.is_writable && !keyed_account.is_writable() { + ic_msg!( + invoke_context, + "{:?}'s writable priviledge escalated ", + account.pubkey + ); return Err(InstructionError::PrivilegeEscalation); } @@ -548,6 +567,11 @@ impl MessageProcessor { keyed_account.signer_key().is_some() // Signed in the parent instruction || signers.contains(&account.pubkey) // Signed by the program ) { + ic_msg!( + invoke_context, + "{:?}'s signer priviledge escalated ", + account.pubkey + ); return Err(InstructionError::PrivilegeEscalation); } } @@ -563,7 +587,10 @@ impl MessageProcessor { return Err(InstructionError::AccountNotExecutable); } } - None => return Err(InstructionError::MissingAccount), + None => { + ic_msg!(invoke_context, "Unknown program {:?}", program_id); + return Err(InstructionError::MissingAccount); + } } let message = Message::new(&[instruction.clone()], None); @@ -579,87 +606,128 @@ impl MessageProcessor { keyed_accounts: &[&KeyedAccount], signers_seeds: &[&[&[u8]]], ) -> Result<(), InstructionError> { - let caller_program_id = invoke_context.get_caller()?; + let invoke_context = RefCell::new(invoke_context); - // Translate and verify caller's data + let (message, executables, accounts, account_refs, caller_privileges) = { + let invoke_context = invoke_context.borrow(); - let signers = signers_seeds - .iter() - .map(|seeds| Pubkey::create_program_address(&seeds, caller_program_id)) - .collect::, solana_sdk::pubkey::PubkeyError>>()?; - let mut caller_privileges = keyed_accounts - .iter() - .map(|keyed_account| keyed_account.is_writable()) - .collect::>(); - caller_privileges.insert(0, false); - let (message, callee_program_id, _) = - Self::create_message(&instruction, &keyed_accounts, &signers)?; - let mut accounts = vec![]; - let mut account_refs = vec![]; - 'root: for account_key in message.account_keys.iter() { - for keyed_account in keyed_accounts { - if account_key == keyed_account.unsigned_key() { - accounts.push(Rc::new(keyed_account.account.clone())); - account_refs.push(keyed_account); - continue 'root; + let caller_program_id = invoke_context.get_caller()?; + + // Translate and verify caller's data + + let signers = signers_seeds + .iter() + .map(|seeds| Pubkey::create_program_address(&seeds, caller_program_id)) + .collect::, solana_sdk::pubkey::PubkeyError>>()?; + let mut caller_privileges = keyed_accounts + .iter() + .map(|keyed_account| keyed_account.is_writable()) + .collect::>(); + caller_privileges.insert(0, false); + let (message, callee_program_id, _) = + Self::create_message(&instruction, &keyed_accounts, &signers, &invoke_context)?; + let mut accounts = vec![]; + let mut account_refs = vec![]; + 'root: for account_key in message.account_keys.iter() { + for keyed_account in keyed_accounts { + if account_key == keyed_account.unsigned_key() { + accounts.push(Rc::new(keyed_account.account.clone())); + account_refs.push(keyed_account); + continue 'root; + } } + ic_msg!( + invoke_context, + "Instruction references an unknown account {:?}", + account_key + ); + return Err(InstructionError::MissingAccount); } - return Err(InstructionError::MissingAccount); - } - // Process instruction + // Process instruction - invoke_context.record_instruction(&instruction); + invoke_context.record_instruction(&instruction); - let program_account = invoke_context - .get_account(&callee_program_id) - .ok_or(InstructionError::MissingAccount)?; - if !program_account.borrow().executable { - return Err(InstructionError::AccountNotExecutable); - } - let programdata_executable = - if program_account.borrow().owner == bpf_loader_upgradeable::id() { - if let UpgradeableLoaderState::Program { - programdata_address, - } = program_account.borrow().state()? - { - if let Some(account) = invoke_context.get_account(&programdata_address) { - Some((programdata_address, account)) + let program_account = + invoke_context + .get_account(&callee_program_id) + .ok_or_else(|| { + ic_msg!(invoke_context, "Unknown program {:?}", callee_program_id); + InstructionError::MissingAccount + })?; + if !program_account.borrow().executable { + return Err(InstructionError::AccountNotExecutable); + } + let programdata_executable = + if program_account.borrow().owner == bpf_loader_upgradeable::id() { + if let UpgradeableLoaderState::Program { + programdata_address, + } = program_account.borrow().state()? + { + if let Some(account) = invoke_context.get_account(&programdata_address) { + Some((programdata_address, account)) + } else { + ic_msg!( + invoke_context, + "Unknown upgradeable programdata account {:?}", + programdata_address, + ); + return Err(InstructionError::MissingAccount); + } } else { + ic_msg!( + invoke_context, + "Upgradeable program account state not valid {:?}", + callee_program_id, + ); return Err(InstructionError::MissingAccount); } } else { - return Err(InstructionError::MissingAccount); - } - } else { - None - }; - let mut executable_accounts = vec![(callee_program_id, program_account)]; - if let Some(programdata) = programdata_executable { - executable_accounts.push(programdata); - } + None + }; + let mut executables = vec![(callee_program_id, program_account)]; + if let Some(programdata) = programdata_executable { + executables.push(programdata); + } + ( + message, + executables, + accounts, + account_refs, + caller_privileges, + ) + }; + #[allow(clippy::deref_addrof)] MessageProcessor::process_cross_program_instruction( &message, - &executable_accounts, + &executables, &accounts, &caller_privileges, - invoke_context, + *(&mut *(invoke_context.borrow_mut())), )?; // Copy results back to caller - for (i, (account, account_ref)) in accounts.iter().zip(account_refs).enumerate() { - let account = account.borrow(); - if message.is_writable(i) && !account.executable { - account_ref.try_account_ref_mut()?.lamports = account.lamports; - account_ref.try_account_ref_mut()?.owner = account.owner; - if account_ref.data_len()? != account.data.len() && account_ref.data_len()? != 0 { - // Only support for `CreateAccount` at this time. - // Need a way to limit total realloc size across multiple CPI calls - return Err(InstructionError::InvalidRealloc); + { + let invoke_context = invoke_context.borrow(); + for (i, (account, account_ref)) in accounts.iter().zip(account_refs).enumerate() { + let account = account.borrow(); + if message.is_writable(i) && !account.executable { + account_ref.try_account_ref_mut()?.lamports = account.lamports; + account_ref.try_account_ref_mut()?.owner = account.owner; + if account_ref.data_len()? != account.data.len() && account_ref.data_len()? != 0 + { + // Only support for `CreateAccount` at this time. + // Need a way to limit total realloc size across multiple CPI calls + ic_msg!( + invoke_context, + "Inner instructions do not support realloc, only SystemProgram::CreateAccount", + ); + return Err(InstructionError::InvalidRealloc); + } + account_ref.try_account_ref_mut()?.data = account.data.clone(); } - account_ref.try_account_ref_mut()?.data = account.data.clone(); } }