From baa6b3a2619e46d643377da64bd3c1ea16fdd1b6 Mon Sep 17 00:00:00 2001 From: Michael Vines Date: Thu, 12 Nov 2020 12:44:37 -0800 Subject: [PATCH] Add stable program logging for BPF and native programs --- core/src/rpc.rs | 15 ++++- program-test/src/lib.rs | 2 +- programs/bpf_loader/src/lib.rs | 34 +++++------- programs/bpf_loader/src/syscalls.rs | 67 +++++++++-------------- run.sh | 2 +- runtime/src/builtins.rs | 55 +++++++++++++++++-- runtime/src/message_processor.rs | 5 +- sdk/src/process_instruction.rs | 85 ++++++++++++++++++++++++++++- web3.js/bin/localnet.sh | 2 +- 9 files changed, 192 insertions(+), 75 deletions(-) diff --git a/core/src/rpc.rs b/core/src/rpc.rs index 9153a82cc5..e4e668ebbd 100644 --- a/core/src/rpc.rs +++ b/core/src/rpc.rs @@ -3788,7 +3788,10 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"err":null, "logs":[]} + "value":{"err":null, "logs":[ + "Program 11111111111111111111111111111111 invoke [1]", + "Program 11111111111111111111111111111111 success" + ]} }, "id": 1, }); @@ -3829,7 +3832,10 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"err":null, "logs":[]} + "value":{"err":null, "logs":[ + "Program 11111111111111111111111111111111 invoke [1]", + "Program 11111111111111111111111111111111 success" + ]} }, "id": 1, }); @@ -3849,7 +3855,10 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"err":null, "logs":[]} + "value":{"err":null, "logs":[ + "Program 11111111111111111111111111111111 invoke [1]", + "Program 11111111111111111111111111111111 success" + ]} }, "id": 1, }); diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index fe64a14067..4b4e02bde2 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -381,7 +381,7 @@ impl Default for ProgramTest { solana_logger::setup_with_default( "solana_bpf_loader=debug,\ solana_rbpf::vm=debug,\ - solana_runtime::message_processor=info,\ + solana_runtime::message_processor=debug,\ solana_runtime::system_instruction_processor=trace,\ solana_program_test=info", ); diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 8f394d24ee..51105b459d 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -25,7 +25,7 @@ use solana_sdk::{ instruction::InstructionError, keyed_account::{is_executable, next_keyed_account, KeyedAccount}, loader_instruction::LoaderInstruction, - process_instruction::{ComputeMeter, Executor, InvokeContext}, + process_instruction::{stable_log, ComputeMeter, Executor, InvokeContext}, program_utils::limited_deserialize, pubkey::Pubkey, }; @@ -63,7 +63,7 @@ pub enum BPFError { impl UserDefinedError for BPFError {} /// Point all log messages to the log collector -macro_rules! log{ +macro_rules! log { ($logger:ident, $message:expr) => { if let Ok(logger) = $logger.try_borrow_mut() { if logger.log_enabled() { @@ -238,6 +238,7 @@ impl Executor for BPFExecutor { invoke_context: &mut dyn InvokeContext, ) -> Result<(), InstructionError> { let logger = invoke_context.get_logger(); + let invoke_depth = invoke_context.invoke_depth(); let mut keyed_accounts_iter = keyed_accounts.iter(); let program = next_keyed_account(&mut keyed_accounts_iter)?; @@ -265,7 +266,7 @@ impl Executor for BPFExecutor { } }; - log!(logger, "Call BPF program {}", program.unsigned_key()); + stable_log::program_invoke(&logger, program.unsigned_key(), invoke_depth); let mut instruction_meter = ThisInstructionMeter::new(compute_meter.clone()); let before = compute_meter.borrow().get_remaining(); const IS_JIT_ENABLED: bool = false; @@ -280,7 +281,8 @@ impl Executor for BPFExecutor { let after = compute_meter.borrow().get_remaining(); log!( logger, - "BPF program consumed {} of {} units", + "Program {} consumed {} of {} compute units", + program.unsigned_key(), before - after, before ); @@ -288,33 +290,25 @@ impl Executor for BPFExecutor { Ok(status) => { if status != SUCCESS { let error: InstructionError = status.into(); - log!( - logger, - "BPF program {} failed: {}", - program.unsigned_key(), - error - ); + stable_log::program_failure(&logger, program.unsigned_key(), &error); return Err(error); } } Err(error) => { - log!( - logger, - "BPF program {} failed: {}", - program.unsigned_key(), - error - ); - return match error { + let error = match error { EbpfError::UserError(BPFError::SyscallError( SyscallError::InstructionError(error), - )) => Err(error), - _ => Err(BPFLoaderError::VirtualMachineFailedToRunProgram.into()), + )) => error, + _ => BPFLoaderError::VirtualMachineFailedToRunProgram.into(), }; + + stable_log::program_failure(&logger, program.unsigned_key(), &error); + return Err(error); } } } deserialize_parameters(program_id, parameter_accounts, ¶meter_bytes)?; - log!(logger, "BPF program {} success", program.unsigned_key()); + stable_log::program_success(&logger, program.unsigned_key()); Ok(()) } } diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index eb613c4881..450646d563 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -21,7 +21,7 @@ use solana_sdk::{ instruction::{AccountMeta, Instruction, InstructionError}, keyed_account::KeyedAccount, message::Message, - process_instruction::{ComputeMeter, InvokeContext, Logger}, + process_instruction::{stable_log, ComputeMeter, InvokeContext, Logger}, program_error::ProgramError, pubkey::{Pubkey, PubkeyError}, }; @@ -369,23 +369,17 @@ impl<'a> SyscallObject for SyscallLog<'a> { memory_mapping: &MemoryMapping, ) -> Result> { self.compute_meter.consume(self.cost)?; - let logger = self - .logger - .try_borrow_mut() - .map_err(|_| SyscallError::InvokeContextBorrowFailed)?; - if logger.log_enabled() { - translate_string_and_do( - memory_mapping, - AccessType::Load, - addr, - len, - &self.loader_id, - &mut |string: &str| { - logger.log(&format!("Program log: {}", string)); - Ok(0) - }, - )?; - } + translate_string_and_do( + memory_mapping, + AccessType::Load, + addr, + len, + &self.loader_id, + &mut |string: &str| { + stable_log::program_log(&self.logger, string); + Ok(0) + }, + )?; Ok(0) } } @@ -407,16 +401,13 @@ impl SyscallObject for SyscallLogU64 { _memory_mapping: &MemoryMapping, ) -> Result> { self.compute_meter.consume(self.cost)?; - let logger = self - .logger - .try_borrow_mut() - .map_err(|_| SyscallError::InvokeContextBorrowFailed)?; - if logger.log_enabled() { - logger.log(&format!( - "Program log: {:#x}, {:#x}, {:#x}, {:#x}, {:#x}", + stable_log::program_log( + &self.logger, + &format!( + "{:#x}, {:#x}, {:#x}, {:#x}, {:#x}", arg1, arg2, arg3, arg4, arg5 - )); - } + ), + ); Ok(0) } } @@ -470,20 +461,14 @@ impl<'a> SyscallObject for SyscallLogPubkey<'a> { memory_mapping: &MemoryMapping, ) -> Result> { self.compute_meter.consume(self.cost)?; - let logger = self - .logger - .try_borrow_mut() - .map_err(|_| SyscallError::InvokeContextBorrowFailed)?; - if logger.log_enabled() { - let pubkey = translate_type!( - memory_mapping, - AccessType::Load, - pubkey_addr, - Pubkey, - self.loader_id - )?; - logger.log(&format!("Program log: {}", pubkey)); - } + let pubkey = translate_type!( + memory_mapping, + AccessType::Load, + pubkey_addr, + Pubkey, + self.loader_id + )?; + stable_log::program_log(&self.logger, &pubkey.to_string()); Ok(0) } } diff --git a/run.sh b/run.sh index 1745ebb5a3..4938280b33 100755 --- a/run.sh +++ b/run.sh @@ -29,7 +29,7 @@ $ok || { exit 1 } -export RUST_LOG=${RUST_LOG:-solana=info} # if RUST_LOG is unset, default to info +export RUST_LOG=${RUST_LOG:-solana=info,solana_runtime::message_processor=debug} # if RUST_LOG is unset, default to info export RUST_BACKTRACE=1 dataDir=$PWD/config/"$(basename "$0" .sh)" ledgerDir=$PWD/config/ledger diff --git a/runtime/src/builtins.rs b/runtime/src/builtins.rs index e0f728e70a..c5f1e52a2e 100644 --- a/runtime/src/builtins.rs +++ b/runtime/src/builtins.rs @@ -2,7 +2,50 @@ use crate::{ bank::{Builtin, Builtins}, system_instruction_processor, }; -use solana_sdk::{feature_set, pubkey::Pubkey, system_program}; +use solana_sdk::{ + feature_set, + instruction::InstructionError, + keyed_account::KeyedAccount, + process_instruction::{stable_log, InvokeContext, ProcessInstructionWithContext}, + pubkey::Pubkey, + system_program, +}; + +fn process_instruction_with_program_logging( + process_instruction: ProcessInstructionWithContext, + program_id: &Pubkey, + keyed_accounts: &[KeyedAccount], + instruction_data: &[u8], + invoke_context: &mut dyn InvokeContext, +) -> Result<(), InstructionError> { + let logger = invoke_context.get_logger(); + stable_log::program_invoke(&logger, program_id, invoke_context.invoke_depth()); + + let result = process_instruction(program_id, keyed_accounts, instruction_data, invoke_context); + + match &result { + Ok(()) => stable_log::program_success(&logger, program_id), + Err(err) => stable_log::program_failure(&logger, program_id, err), + } + result +} + +macro_rules! with_program_logging { + ($process_instruction:expr) => { + |program_id: &Pubkey, + keyed_accounts: &[KeyedAccount], + instruction_data: &[u8], + invoke_context: &mut dyn InvokeContext| { + process_instruction_with_program_logging( + $process_instruction, + program_id, + keyed_accounts, + instruction_data, + invoke_context, + ) + } + }; +} /// Builtin programs that are always available fn genesis_builtins() -> Vec { @@ -10,24 +53,26 @@ fn genesis_builtins() -> Vec { Builtin::new( "system_program", system_program::id(), - system_instruction_processor::process_instruction, + with_program_logging!(system_instruction_processor::process_instruction), ), Builtin::new( "vote_program", solana_vote_program::id(), - solana_vote_program::vote_instruction::process_instruction, + with_program_logging!(solana_vote_program::vote_instruction::process_instruction), ), // Remove legacy_stake_processor and move stake_instruction::process_instruction back to // genesis_builtins around the v1.6 timeframe Builtin::new( "stake_program", solana_stake_program::id(), - solana_stake_program::legacy_stake_processor::process_instruction, + with_program_logging!( + solana_stake_program::legacy_stake_processor::process_instruction + ), ), Builtin::new( "config_program", solana_config_program::id(), - solana_config_program::config_processor::process_instruction, + with_program_logging!(solana_config_program::config_processor::process_instruction), ), ] } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 13deecf374..8323d325b6 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -256,6 +256,9 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { fn pop(&mut self) { self.program_ids.pop(); } + fn invoke_depth(&self) -> usize { + self.program_ids.len() + } fn verify_and_update( &mut self, message: &Message, @@ -314,7 +317,7 @@ impl Logger for ThisLogger { log_enabled!(log::Level::Info) || self.log_collector.is_some() } fn log(&self, message: &str) { - info!("{}", message); + debug!("{}", message); if let Some(log_collector) = &self.log_collector { log_collector.log(message); } diff --git a/sdk/src/process_instruction.rs b/sdk/src/process_instruction.rs index 0785d10168..6c65c285df 100644 --- a/sdk/src/process_instruction.rs +++ b/sdk/src/process_instruction.rs @@ -33,6 +33,8 @@ pub trait InvokeContext { fn push(&mut self, key: &Pubkey) -> Result<(), InstructionError>; /// Pop a program ID off of the invocation stack fn pop(&mut self); + /// Current depth of the invocation stake + fn invoke_depth(&self) -> usize; /// Verify and update PreAccount state based on program execution fn verify_and_update( &mut self, @@ -155,10 +157,81 @@ pub trait ComputeMeter { /// Log messages pub trait Logger { fn log_enabled(&self) -> bool; - /// Log a message + + /// 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); } +/// +/// Stable program log messages +/// +/// The format of these log messages should not be modified to avoid breaking downstream consumers +/// of program logging +/// +pub mod stable_log { + use super::*; + + /// Log a program invoke. + /// + /// The general form is: + /// "Program
invoke []" + pub fn program_invoke( + logger: &Rc>, + 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)); + } + } + } + + /// Log a message from the program itself. + /// + /// The general form is: + /// "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)) + } + } + } + + /// Log successful program execution. + /// + /// 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)); + } + } + } + + /// Log program execution failure + /// + /// The general form is: + /// "Program
failed: " + pub fn program_failure( + logger: &Rc>, + 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)); + } + } + } +} + /// Program executor pub trait Executor: Debug + Send + Sync { /// Execute the program @@ -208,6 +281,7 @@ pub struct MockInvokeContext { pub bpf_compute_budget: BpfComputeBudget, pub compute_meter: MockComputeMeter, pub programs: Vec<(Pubkey, ProcessInstructionWithContext)>, + invoke_depth: usize, } impl Default for MockInvokeContext { fn default() -> Self { @@ -219,14 +293,21 @@ impl Default for MockInvokeContext { remaining: std::i64::MAX as u64, }, programs: vec![], + invoke_depth: 0, } } } impl InvokeContext for MockInvokeContext { fn push(&mut self, _key: &Pubkey) -> Result<(), InstructionError> { + self.invoke_depth += 1; Ok(()) } - fn pop(&mut self) {} + fn pop(&mut self) { + self.invoke_depth -= 1; + } + fn invoke_depth(&self) -> usize { + self.invoke_depth + } fn verify_and_update( &mut self, _message: &Message, diff --git a/web3.js/bin/localnet.sh b/web3.js/bin/localnet.sh index 5caee61e1a..2551a077de 100755 --- a/web3.js/bin/localnet.sh +++ b/web3.js/bin/localnet.sh @@ -79,7 +79,7 @@ up) ( set -x - RUST_LOG=${RUST_LOG:-solana=info} + RUST_LOG=${RUST_LOG:-solana=info,solana_runtime::message_processor=debug} ARGS=( --detach --name solana-localnet