From 2da0dfbf3313226d402e6e6d7641cb55ee26dd5b Mon Sep 17 00:00:00 2001 From: Michael Vines Date: Fri, 5 Jun 2020 11:46:19 -0700 Subject: [PATCH] RPC simulateTransaction endpoint now returns program log output --- client/src/rpc_client.rs | 2 +- client/src/rpc_response.rs | 7 + core/src/banking_stage.rs | 2 +- core/src/rpc.rs | 47 +++-- docs/src/apps/jsonrpc-api.md | 4 + programs/bpf/benches/bpf_loader.rs | 4 + programs/bpf_loader/src/lib.rs | 8 + programs/bpf_loader/src/syscalls.rs | 270 +++++++++++++++++++--------- runtime/src/bank.rs | 6 +- runtime/src/lib.rs | 1 + runtime/src/log_collector.rs | 16 ++ runtime/src/message_processor.rs | 46 +++-- sdk/src/entrypoint_native.rs | 2 + 13 files changed, 295 insertions(+), 120 deletions(-) create mode 100644 runtime/src/log_collector.rs diff --git a/client/src/rpc_client.rs b/client/src/rpc_client.rs index f2470ad103a253..58c86bb6ca92a2 100644 --- a/client/src/rpc_client.rs +++ b/client/src/rpc_client.rs @@ -129,7 +129,7 @@ impl RpcClient { &self, transaction: &Transaction, sig_verify: bool, - ) -> RpcResult { + ) -> RpcResult { let serialized_encoded = bs58::encode(serialize(transaction).unwrap()).into_string(); self.send( RpcRequest::SimulateTransaction, diff --git a/client/src/rpc_response.rs b/client/src/rpc_response.rs index 90a139136d8adc..b78f42fe4a4f42 100644 --- a/client/src/rpc_response.rs +++ b/client/src/rpc_response.rs @@ -211,6 +211,13 @@ pub struct RpcSignatureConfirmation { pub status: Result<()>, } +#[derive(Serialize, Deserialize, Clone, Debug)] +#[serde(rename_all = "camelCase")] +pub struct RpcSimulateTransactionResult { + pub err: Option, + pub logs: Option>, +} + #[derive(Serialize, Deserialize, Clone, Debug)] #[serde(rename_all = "camelCase")] pub struct RpcStorageTurn { diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 4feffefbaeb3c4..a5a992a025dba2 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -514,7 +514,7 @@ impl BankingStage { vec![] }; let (mut loaded_accounts, results, mut retryable_txs, tx_count, signature_count) = - bank.load_and_execute_transactions(batch, MAX_PROCESSING_AGE); + bank.load_and_execute_transactions(batch, MAX_PROCESSING_AGE, None); load_execute_time.stop(); let freeze_lock = bank.freeze_lock(); diff --git a/core/src/rpc.rs b/core/src/rpc.rs index f303e26a7578fd..b0295e60d38609 100644 --- a/core/src/rpc.rs +++ b/core/src/rpc.rs @@ -25,7 +25,7 @@ use solana_ledger::{ bank_forks::BankForks, blockstore::Blockstore, blockstore_db::BlockstoreError, }; use solana_perf::packet::PACKET_DATA_SIZE; -use solana_runtime::{accounts::AccountAddressFilter, bank::Bank}; +use solana_runtime::{accounts::AccountAddressFilter, bank::Bank, log_collector::LogCollector}; use solana_sdk::{ clock::{Epoch, Slot, UnixTimestamp}, commitment_config::{CommitmentConfig, CommitmentLevel}, @@ -718,14 +718,22 @@ fn verify_signature(input: &str) -> Result { } /// Run transactions against a frozen bank without committing the results -fn run_transaction_simulation(bank: &Bank, transaction: Transaction) -> transaction::Result<()> { +fn run_transaction_simulation( + bank: &Bank, + transaction: Transaction, +) -> (transaction::Result<()>, Vec) { assert!(bank.is_frozen(), "simulation bank must be frozen"); let txs = &[transaction]; let batch = bank.prepare_simulation_batch(txs); + let log_collector = LogCollector::default(); let (_loaded_accounts, executed, _retryable_transactions, _transaction_count, _signature_count) = - bank.load_and_execute_transactions(&batch, solana_sdk::clock::MAX_PROCESSING_AGE); - executed[0].0.clone().map(|_| ()) + bank.load_and_execute_transactions( + &batch, + solana_sdk::clock::MAX_PROCESSING_AGE, + Some(&log_collector), + ); + (executed[0].0.clone().map(|_| ()), log_collector.output()) } #[derive(Clone)] @@ -932,7 +940,7 @@ pub trait RpcSol { meta: Self::Metadata, data: String, config: Option, - ) -> RpcResponse; + ) -> RpcResponse; #[rpc(meta, name = "getSlotLeader")] fn get_slot_leader( @@ -1452,7 +1460,7 @@ impl RpcSol for RpcSolImpl { } let bank = &*meta.request_processor.read().unwrap().bank(None)?; - if let Err(err) = run_transaction_simulation(&bank, transaction) { + if let (Err(err), _log_output) = run_transaction_simulation(&bank, transaction) { // Note: it's possible that the transaction simulation failed but the actual // transaction would succeed, such as when a transaction depends on an earlier // transaction that has yet to reach max confirmations. In these cases the user @@ -1486,7 +1494,7 @@ impl RpcSol for RpcSolImpl { meta: Self::Metadata, data: String, config: Option, - ) -> RpcResponse { + ) -> RpcResponse { let (_, transaction) = deserialize_bs58_transaction(data)?; let config = config.unwrap_or_default(); @@ -1497,18 +1505,19 @@ impl RpcSol for RpcSolImpl { }; let bank = &*meta.request_processor.read().unwrap().bank(None)?; - - if result.is_ok() { - result = run_transaction_simulation(&bank, transaction); - } + let logs = if result.is_ok() { + let sim_result = run_transaction_simulation(&bank, transaction); + result = sim_result.0; + Some(sim_result.1) + } else { + None + }; new_response( &bank, - TransactionStatus { - slot: bank.slot(), - confirmations: Some(0), - status: result.clone(), + RpcSimulateTransactionResult { err: result.err(), + logs, }, ) } @@ -2400,7 +2409,7 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"confirmations":0,"slot": 0,"status":{"Ok":null},"err":null} + "value":{"err":null, "logs":[]} }, "id": 1, }); @@ -2420,7 +2429,7 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"confirmations":0,"slot":0,"status":{"Err":"SignatureFailure"},"err":"SignatureFailure"} + "value":{"err":"SignatureFailure", "logs":null} }, "id": 1, }); @@ -2440,7 +2449,7 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"confirmations":0,"slot": 0,"status":{"Ok":null},"err":null} + "value":{"err":null, "logs":[]} }, "id": 1, }); @@ -2460,7 +2469,7 @@ pub mod tests { "jsonrpc": "2.0", "result": { "context":{"slot":0}, - "value":{"confirmations":0,"slot": 0,"status":{"Ok":null},"err":null} + "value":{"err":null, "logs":[]} }, "id": 1, }); diff --git a/docs/src/apps/jsonrpc-api.md b/docs/src/apps/jsonrpc-api.md index 0eda6a9d7b93d9..fc5bd087c3bf8d 100644 --- a/docs/src/apps/jsonrpc-api.md +++ b/docs/src/apps/jsonrpc-api.md @@ -1107,6 +1107,10 @@ Simulate sending a transaction #### Results: An RpcResponse containing a TransactionStatus object +The result will be an RpcResponse JSON object with `value` set to a JSON object with the following fields: + +* `err: ` - Error if transaction failed, null if transaction succeeded. [TransactionError definitions](https://github.com/solana-labs/solana/blob/master/sdk/src/transaction.rs#L14) +* `logs: ` - Array of log messages the transaction instructions output during execution, null if simulation failed before the transaction was able to execute (for example due to an invalid blockhash or signature verification failure) #### Example: diff --git a/programs/bpf/benches/bpf_loader.rs b/programs/bpf/benches/bpf_loader.rs index a78cd22c10fa3f..b1729beff7c02b 100644 --- a/programs/bpf/benches/bpf_loader.rs +++ b/programs/bpf/benches/bpf_loader.rs @@ -155,4 +155,8 @@ impl InvokeContext for MockInvokeContext { fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &[] } + fn log_enabled(&self) -> bool { + false + } + fn log(&mut self, _message: &str) {} } diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 2b4b66d068814b..d157db35d03257 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -267,6 +267,7 @@ mod tests { #[derive(Debug, Default)] pub struct MockInvokeContext { key: Pubkey, + pub log: Vec, } impl InvokeContext for MockInvokeContext { fn push(&mut self, _key: &Pubkey) -> Result<(), InstructionError> { @@ -287,6 +288,13 @@ mod tests { fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &[] } + fn log_enabled(&self) -> bool { + true + } + fn log(&mut self, message: &str) { + info!("[MockInvokeContext::log] {}", message); + self.log.push(message.to_string()); + } } #[test] diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index a3a928feb6d3cf..878c27439aa3d4 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -77,13 +77,30 @@ pub fn register_syscalls<'a>( ) -> Result> { // Syscall function common across languages vm.register_syscall_ex("abort", syscall_abort)?; - vm.register_syscall_ex("sol_panic_", syscall_sol_panic)?; - vm.register_syscall_ex("sol_log_", syscall_sol_log)?; - vm.register_syscall_ex("sol_log_64_", syscall_sol_log_u64)?; - // Cross-program invocation syscalls { let invoke_context = Rc::new(RefCell::new(invoke_context)); + + vm.register_syscall_with_context_ex( + "sol_panic_", + Box::new(SyscallPanic { + invoke_context: invoke_context.clone(), + }), + )?; + vm.register_syscall_with_context_ex( + "sol_log_", + Box::new(SyscallLog { + invoke_context: invoke_context.clone(), + }), + )?; + vm.register_syscall_with_context_ex( + "sol_log_64_", + Box::new(SyscallLogU64 { + invoke_context: invoke_context.clone(), + }), + )?; + + // Cross-program invocation syscalls vm.register_syscall_with_context_ex( "sol_invoke_signed_c", Box::new(SyscallProcessSolInstructionC { @@ -184,7 +201,7 @@ fn translate_string_and_do( addr: u64, len: u64, regions: &[MemoryRegion], - work: &dyn Fn(&str) -> Result>, + work: &mut dyn FnMut(&str) -> Result>, ) -> Result> { let buf = translate_slice!(u8, addr, len, regions)?; let i = match buf.iter().position(|byte| *byte == 0) { @@ -215,56 +232,101 @@ pub fn syscall_abort( /// Panic syscall function, called when the BPF program calls 'sol_panic_()` /// Causes the BPF program to be halted immediately -pub fn syscall_sol_panic( - file: u64, - len: u64, - line: u64, - column: u64, - _arg5: u64, - ro_regions: &[MemoryRegion], - _rw_regions: &[MemoryRegion], -) -> Result> { - translate_string_and_do(file, len, ro_regions, &|string: &str| { - Err(SyscallError::Panic(string.to_string(), line, column).into()) - }) +pub struct SyscallPanic<'a> { + invoke_context: Rc>, +} +impl<'a> SyscallPanic<'a> { + fn get_context_mut(&self) -> Result, EbpfError> { + self.invoke_context + .try_borrow_mut() + .map_err(|_| SyscallError::InvokeContextBorrowFailed.into()) + } +} +impl<'a> SyscallObject for SyscallPanic<'a> { + fn call( + &mut self, + file: u64, + len: u64, + line: u64, + column: u64, + _arg5: u64, + ro_regions: &[MemoryRegion], + _rw_regions: &[MemoryRegion], + ) -> Result> { + let mut invoke_context = self.get_context_mut()?; + translate_string_and_do(file, len, ro_regions, &mut |string: &str| { + if invoke_context.log_enabled() { + invoke_context.log(&format!("panicked at '{}' on {}:{}", string, line, column)); + } + Err(SyscallError::Panic(string.to_string(), line, column).into()) + }) + } } /// Log a user's info message -pub fn syscall_sol_log( - addr: u64, - len: u64, - _arg3: u64, - _arg4: u64, - _arg5: u64, - ro_regions: &[MemoryRegion], - _rw_regions: &[MemoryRegion], -) -> Result> { - if log_enabled!(log::Level::Info) { - translate_string_and_do(addr, len, ro_regions, &|string: &str| { - info!("info!: {}", string); - Ok(0) - })?; +pub struct SyscallLog<'a> { + invoke_context: Rc>, +} +impl<'a> SyscallLog<'a> { + fn get_context_mut(&self) -> Result, EbpfError> { + self.invoke_context + .try_borrow_mut() + .map_err(|_| SyscallError::InvokeContextBorrowFailed.into()) + } +} +impl<'a> SyscallObject for SyscallLog<'a> { + fn call( + &mut self, + addr: u64, + len: u64, + _arg3: u64, + _arg4: u64, + _arg5: u64, + ro_regions: &[MemoryRegion], + _rw_regions: &[MemoryRegion], + ) -> Result> { + let mut invoke_context = self.get_context_mut()?; + if invoke_context.log_enabled() { + translate_string_and_do(addr, len, ro_regions, &mut |string: &str| { + invoke_context.log(string); + Ok(0) + })?; + } + Ok(0) } - Ok(0) } /// Log 5 64-bit values -pub fn syscall_sol_log_u64( - arg1: u64, - arg2: u64, - arg3: u64, - arg4: u64, - arg5: u64, - _ro_regions: &[MemoryRegion], - _rw_regions: &[MemoryRegion], -) -> Result> { - if log_enabled!(log::Level::Info) { - info!( - "info!: {:#x}, {:#x}, {:#x}, {:#x}, {:#x}", - arg1, arg2, arg3, arg4, arg5 - ); +pub struct SyscallLogU64<'a> { + invoke_context: Rc>, +} +impl<'a> SyscallLogU64<'a> { + fn get_context_mut(&self) -> Result, EbpfError> { + self.invoke_context + .try_borrow_mut() + .map_err(|_| SyscallError::InvokeContextBorrowFailed.into()) + } +} +impl<'a> SyscallObject for SyscallLogU64<'a> { + fn call( + &mut self, + arg1: u64, + arg2: u64, + arg3: u64, + arg4: u64, + arg5: u64, + _ro_regions: &[MemoryRegion], + _rw_regions: &[MemoryRegion], + ) -> Result> { + let mut invoke_context = self.get_context_mut()?; + if invoke_context.log_enabled() { + invoke_context.log(&format!( + "{:#x}, {:#x}, {:#x}, {:#x}, {:#x}", + arg1, arg2, arg3, arg4, arg5 + )); + } + Ok(0) } - Ok(0) } /// Dynamic memory allocation syscall called when the BPF program calls @@ -801,6 +863,8 @@ fn call<'a>( #[cfg(test)] mod tests { use super::*; + use crate::tests::MockInvokeContext; + use solana_sdk::entrypoint_native::InvokeContext; #[test] fn test_translate() { @@ -904,7 +968,7 @@ mod tests { }]; assert_eq!( 42, - translate_string_and_do(100, string.len() as u64, ®ions, &|string: &str| { + translate_string_and_do(100, string.len() as u64, ®ions, &mut |string: &str| { assert_eq!(string, "Gaggablaghblagh!"); Ok(42) }) @@ -924,29 +988,41 @@ mod tests { #[should_panic(expected = "UserError(SyscallError(Panic(\"Gaggablaghblagh!\", 42, 84)))")] fn test_syscall_sol_panic() { let string = "Gaggablaghblagh!"; - let addr = string.as_ptr() as *const _ as u64; - let ro_region = MemoryRegion { - addr_host: addr, - addr_vm: 100, - len: string.len() as u64, + + let mut mock_invoke_context = MockInvokeContext::default(); + let result = { + let invoke_context: &mut dyn InvokeContext = &mut mock_invoke_context; + let mut syscall_sol_panic = SyscallPanic { + invoke_context: Rc::new(RefCell::new(invoke_context)), + }; + + let addr = string.as_ptr() as *const _ as u64; + let ro_region = MemoryRegion { + addr_host: addr, + addr_vm: 100, + len: string.len() as u64, + }; + let rw_region = MemoryRegion::default(); + syscall_sol_panic.call( + 100, + string.len() as u64, + 42, + 84, + 0, + &[ro_region], + &[rw_region], + ) }; - let rw_region = MemoryRegion::default(); - syscall_sol_panic( - 100, - string.len() as u64, - 42, - 84, - 0, - &[ro_region], - &[rw_region], - ) - .unwrap(); + assert_eq!(mock_invoke_context.log.len(), 1); + assert_eq!( + mock_invoke_context.log[0], + "panicked at \'Gaggablaghblagh!\' on 42:84" + ); + + result.unwrap(); } - // Ignore this test: solana_logger conflicts when running tests concurrently, - // this results in the bad string length being ignored and not returning an error #[test] - #[ignore] fn test_syscall_sol_log() { let string = "Gaggablaghblagh!"; let addr = string.as_ptr() as *const _ as u64; @@ -956,31 +1032,51 @@ mod tests { len: string.len() as u64, }]; let rw_regions = &[MemoryRegion::default()]; - solana_logger::setup_with_default("solana=info"); - syscall_sol_log(100, string.len() as u64, 0, 0, 0, ro_regions, rw_regions).unwrap(); - solana_logger::setup_with_default("solana=info"); - syscall_sol_log( - 100, - string.len() as u64 * 2, - 0, - 0, - 0, - ro_regions, - rw_regions, - ) - .unwrap_err(); + + let mut mock_invoke_context = MockInvokeContext::default(); + { + let invoke_context: &mut dyn InvokeContext = &mut mock_invoke_context; + let mut syscall_sol_log = SyscallLog { + invoke_context: Rc::new(RefCell::new(invoke_context)), + }; + + syscall_sol_log + .call(100, string.len() as u64, 0, 0, 0, ro_regions, rw_regions) + .unwrap(); + + syscall_sol_log + .call( + 100, + string.len() as u64 * 2, // AccessViolation + 0, + 0, + 0, + ro_regions, + rw_regions, + ) + .unwrap_err(); + } + assert_eq!(mock_invoke_context.log.len(), 1); + assert_eq!(mock_invoke_context.log[0], "Gaggablaghblagh!"); } - // Ignore this test: solana_logger conflicts when running tests concurrently, - // this results in the bad string length being ignored and not returning an error #[test] - #[ignore] fn test_syscall_sol_log_u64() { - solana_logger::setup_with_default("solana=info"); + let mut mock_invoke_context = MockInvokeContext::default(); + { + let invoke_context: &mut dyn InvokeContext = &mut mock_invoke_context; + let mut syscall_sol_log_u64 = SyscallLogU64 { + invoke_context: Rc::new(RefCell::new(invoke_context)), + }; - let ro_regions = &[MemoryRegion::default()]; - let rw_regions = &[MemoryRegion::default()]; - syscall_sol_log_u64(1, 2, 3, 4, 5, ro_regions, rw_regions).unwrap(); + let ro_regions = &[MemoryRegion::default()]; + let rw_regions = &[MemoryRegion::default()]; + syscall_sol_log_u64 + .call(1, 2, 3, 4, 5, ro_regions, rw_regions) + .unwrap(); + } + assert_eq!(mock_invoke_context.log.len(), 1); + assert_eq!(mock_invoke_context.log[0], "0x1, 0x2, 0x3, 0x4, 0x5"); } #[test] diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index b1515adb824ead..891b5ced0fc68e 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -12,6 +12,7 @@ use crate::{ blockhash_queue::BlockhashQueue, builtin_programs::{get_builtin_programs, get_epoch_activated_builtin_programs}, epoch_stakes::{EpochStakes, NodeVoteAccounts}, + log_collector::LogCollector, message_processor::MessageProcessor, nonce_utils, rent_collector::RentCollector, @@ -1333,6 +1334,7 @@ impl Bank { &self, batch: &TransactionBatch, max_age: usize, + log_collector: Option<&LogCollector>, ) -> ( Vec<(Result, Option)>, Vec, @@ -1392,6 +1394,7 @@ impl Bank { &loader_refcells, &account_refcells, &self.rent_collector, + log_collector, ); Self::from_refcells(accounts, loaders, account_refcells, loader_refcells); @@ -1412,6 +1415,7 @@ impl Bank { execution_time.as_us(), txs.len(), ); + let mut tx_count: u64 = 0; let err_count = &mut error_counters.total; for ((r, _hash_age_kind), tx) in executed.iter().zip(txs.iter()) { @@ -1955,7 +1959,7 @@ impl Bank { vec![] }; let (mut loaded_accounts, executed, _, tx_count, signature_count) = - self.load_and_execute_transactions(batch, max_age); + self.load_and_execute_transactions(batch, max_age, None); let results = self.commit_transactions( batch.transactions(), diff --git a/runtime/src/lib.rs b/runtime/src/lib.rs index 7a975506cf5652..fe261d6662c851 100644 --- a/runtime/src/lib.rs +++ b/runtime/src/lib.rs @@ -11,6 +11,7 @@ pub mod epoch_stakes; pub mod genesis_utils; mod legacy_system_instruction_processor0; pub mod loader_utils; +pub mod log_collector; pub mod message_processor; mod native_loader; pub mod nonce_utils; diff --git a/runtime/src/log_collector.rs b/runtime/src/log_collector.rs new file mode 100644 index 00000000000000..0d0710e70861d3 --- /dev/null +++ b/runtime/src/log_collector.rs @@ -0,0 +1,16 @@ +use std::cell::RefCell; + +#[derive(Default)] +pub struct LogCollector { + messages: RefCell>, +} + +impl LogCollector { + pub fn log(&self, message: &str) { + self.messages.borrow_mut().push(message.to_string()) + } + + pub fn output(self) -> Vec { + self.messages.into_inner() + } +} diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 3f727df3cf7017..737743cc06c0a1 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -1,4 +1,7 @@ -use crate::{native_loader::NativeLoader, rent_collector::RentCollector}; +use crate::{ + log_collector::LogCollector, native_loader::NativeLoader, rent_collector::RentCollector, +}; +use log::*; use serde::{Deserialize, Serialize}; use solana_sdk::{ account::{create_keyed_readonly_accounts, Account, KeyedAccount}, @@ -152,19 +155,22 @@ impl PreAccount { } #[derive(Default)] -pub struct ThisInvokeContext { +pub struct ThisInvokeContext<'a> { pub program_ids: Vec, pub rent: Rent, pub pre_accounts: Vec, pub programs: Vec<(Pubkey, ProcessInstruction)>, + pub log_collector: Option<&'a LogCollector>, } -impl ThisInvokeContext { + +impl<'a> ThisInvokeContext<'a> { const MAX_INVOCATION_DEPTH: usize = 5; pub fn new( program_id: &Pubkey, rent: Rent, pre_accounts: Vec, programs: Vec<(Pubkey, ProcessInstruction)>, + log_collector: Option<&'a LogCollector>, ) -> Self { let mut program_ids = Vec::with_capacity(Self::MAX_INVOCATION_DEPTH); program_ids.push(*program_id); @@ -173,10 +179,12 @@ impl ThisInvokeContext { rent, pre_accounts, programs, + log_collector, } } } -impl InvokeContext for ThisInvokeContext { + +impl<'a> InvokeContext for ThisInvokeContext<'a> { fn push(&mut self, key: &Pubkey) -> Result<(), InstructionError> { if self.program_ids.len() >= Self::MAX_INVOCATION_DEPTH { return Err(InstructionError::CallDepth); @@ -218,6 +226,17 @@ impl InvokeContext for ThisInvokeContext { fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &self.programs } + + fn log_enabled(&self) -> bool { + log_enabled!(log::Level::Info) || self.log_collector.is_some() + } + + fn log(&mut self, message: &str) { + info!("{}", message); + if let Some(log_collector) = self.log_collector { + log_collector.log(message); + } + } } pub type ProcessInstructionWithContext = @@ -483,6 +502,7 @@ impl MessageProcessor { executable_accounts: &[(Pubkey, RefCell)], accounts: &[Rc>], rent_collector: &RentCollector, + log_collector: Option<&LogCollector>, ) -> Result<(), InstructionError> { let pre_accounts = Self::create_pre_accounts(message, instruction, accounts); let mut invoke_context = ThisInvokeContext::new( @@ -490,6 +510,7 @@ impl MessageProcessor { rent_collector.rent, pre_accounts, self.programs.clone(), + log_collector, ); let keyed_accounts = Self::create_keyed_accounts(message, instruction, executable_accounts, accounts)?; @@ -514,6 +535,7 @@ impl MessageProcessor { loaders: &[Vec<(Pubkey, RefCell)>], accounts: &[Rc>], rent_collector: &RentCollector, + log_collector: Option<&LogCollector>, ) -> Result<(), TransactionError> { for (instruction_index, instruction) in message.instructions.iter().enumerate() { self.execute_instruction( @@ -522,6 +544,7 @@ impl MessageProcessor { &loaders[instruction_index], accounts, rent_collector, + log_collector, ) .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } @@ -561,7 +584,7 @@ mod tests { )) } let mut invoke_context = - ThisInvokeContext::new(&program_ids[0], Rent::default(), pre_accounts, vec![]); + ThisInvokeContext::new(&program_ids[0], Rent::default(), pre_accounts, vec![], None); // Check call depth increases and has a limit let mut depth_reached = 1; @@ -1085,7 +1108,7 @@ mod tests { )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!(result, Ok(())); assert_eq!(accounts[0].borrow().lamports, 100); assert_eq!(accounts[1].borrow().lamports, 0); @@ -1097,7 +1120,7 @@ mod tests { )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!( result, Err(TransactionError::InstructionError( @@ -1113,7 +1136,7 @@ mod tests { )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!( result, Err(TransactionError::InstructionError( @@ -1210,7 +1233,7 @@ mod tests { account_metas.clone(), )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!( result, Err(TransactionError::InstructionError( @@ -1226,7 +1249,7 @@ mod tests { account_metas.clone(), )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!(result, Ok(())); // Do work on the same account but at different location in keyed_accounts[] @@ -1239,7 +1262,7 @@ mod tests { account_metas, )]); let result = - message_processor.process_message(&message, &loaders, &accounts, &rent_collector); + message_processor.process_message(&message, &loaders, &accounts, &rent_collector, None); assert_eq!(result, Ok(())); assert_eq!(accounts[0].borrow().lamports, 80); assert_eq!(accounts[1].borrow().lamports, 20); @@ -1310,6 +1333,7 @@ mod tests { Rent::default(), vec![owned_preaccount, not_owned_preaccount], vec![], + None, ); let metas = vec![ AccountMeta::new(owned_key, false), diff --git a/sdk/src/entrypoint_native.rs b/sdk/src/entrypoint_native.rs index bdf9328f7c1821..278a5214f8fe6a 100644 --- a/sdk/src/entrypoint_native.rs +++ b/sdk/src/entrypoint_native.rs @@ -160,4 +160,6 @@ pub trait InvokeContext { ) -> Result<(), InstructionError>; fn get_caller(&self) -> Result<&Pubkey, InstructionError>; fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)]; + fn log_enabled(&self) -> bool; + fn log(&mut self, message: &str); }