From b6a95737487b9603068b75f6eda65b9a6fd2ca6f Mon Sep 17 00:00:00 2001 From: Jack May Date: Sat, 13 Jun 2020 13:20:08 -0700 Subject: [PATCH] Route all loader messages to log collector (#10528) --- Cargo.lock | 2 - core/src/rpc.rs | 15 +- programs/bpf/Cargo.lock | 2 - programs/bpf/benches/bpf_loader.rs | 20 +- programs/bpf_loader/Cargo.toml | 2 - programs/bpf_loader/src/lib.rs | 87 ++++++--- programs/bpf_loader/src/syscalls.rs | 280 ++++++++++++---------------- runtime/src/bank.rs | 4 +- runtime/src/log_collector.rs | 5 +- runtime/src/message_processor.rs | 46 ++--- sdk/src/entrypoint_native.rs | 7 +- 11 files changed, 240 insertions(+), 230 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index f016086be..5f43885e1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3741,11 +3741,9 @@ dependencies = [ "bincode", "byteorder", "jemalloc-sys", - "log 0.4.8", "num-derive 0.3.0", "num-traits", "rand 0.7.3", - "solana-logger", "solana-runtime", "solana-sdk", "solana_rbpf", diff --git a/core/src/rpc.rs b/core/src/rpc.rs index d7dc624cf..9fe2ea360 100644 --- a/core/src/rpc.rs +++ b/core/src/rpc.rs @@ -47,6 +47,7 @@ use std::{ cmp::{max, min}, collections::{HashMap, HashSet}, net::SocketAddr, + rc::Rc, str::FromStr, sync::{Arc, RwLock}, }; @@ -730,14 +731,18 @@ fn run_transaction_simulation( 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) = + let log_collector = Rc::new(LogCollector::default()); + let (_loaded_accounts, executed, _retryable_transactions, _transaction_count, _signature_count) = { bank.load_and_execute_transactions( &batch, solana_sdk::clock::MAX_PROCESSING_AGE, - Some(&log_collector), - ); - (executed[0].0.clone().map(|_| ()), log_collector.output()) + Some(log_collector.clone()), + ) + }; + ( + executed[0].0.clone().map(|_| ()), + Rc::try_unwrap(log_collector).unwrap_or_default().into(), + ) } #[rpc] diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index 34d2598ad..43c0d2cb0 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -1337,10 +1337,8 @@ dependencies = [ "bincode 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)", "byteorder 1.3.4 (registry+https://github.com/rust-lang/crates.io-index)", "jemalloc-sys 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)", "num-derive 0.3.0 (registry+https://github.com/rust-lang/crates.io-index)", "num-traits 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)", - "solana-logger 1.3.0", "solana-runtime 1.3.0", "solana-sdk 1.3.0", "solana_rbpf 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/programs/bpf/benches/bpf_loader.rs b/programs/bpf/benches/bpf_loader.rs index b1729beff..d613373e6 100644 --- a/programs/bpf/benches/bpf_loader.rs +++ b/programs/bpf/benches/bpf_loader.rs @@ -6,7 +6,7 @@ use byteorder::{ByteOrder, LittleEndian, WriteBytesExt}; use solana_rbpf::EbpfVm; use solana_sdk::{ account::Account, - entrypoint_native::{InvokeContext, ProcessInstruction}, + entrypoint_native::{InvokeContext, Logger, ProcessInstruction}, instruction::{CompiledInstruction, InstructionError}, message::Message, pubkey::Pubkey, @@ -135,6 +135,7 @@ fn bench_program_alu(bencher: &mut Bencher) { #[derive(Debug, Default)] pub struct MockInvokeContext { key: Pubkey, + mock_logger: MockLogger, } impl InvokeContext for MockInvokeContext { fn push(&mut self, _key: &Pubkey) -> Result<(), InstructionError> { @@ -155,8 +156,19 @@ impl InvokeContext for MockInvokeContext { fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &[] } - fn log_enabled(&self) -> bool { - false + fn get_logger(&self) -> Rc> { + Rc::new(RefCell::new(self.mock_logger.clone())) + } +} +#[derive(Debug, Default, Clone)] +pub struct MockLogger { + pub log: Rc>>, +} +impl Logger for MockLogger { + fn log_enabled(&self) -> bool { + true + } + fn log(&mut self, message: &str) { + self.log.borrow_mut().push(message.to_string()); } - fn log(&mut self, _message: &str) {} } diff --git a/programs/bpf_loader/Cargo.toml b/programs/bpf_loader/Cargo.toml index 5884e3f63..69c681aac 100644 --- a/programs/bpf_loader/Cargo.toml +++ b/programs/bpf_loader/Cargo.toml @@ -12,10 +12,8 @@ edition = "2018" bincode = "1.2.1" byteorder = "1.3.4" jemalloc-sys = { version = "0.3.2", features = ["disable_initial_exec_tls"] } -log = "0.4.8" num-derive = { version = "0.3" } num-traits = { version = "0.2" } -solana-logger = { path = "../../logger", version = "1.3.0" } solana-runtime = { path = "../../runtime", version = "1.3.0" } solana-sdk = { path = "../../sdk", version = "1.3.0" } solana_rbpf = "=0.1.28" diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index d157db35d..61c631ede 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -5,7 +5,6 @@ pub mod syscalls; use crate::{bpf_verifier::VerifierError, syscalls::SyscallError}; use byteorder::{ByteOrder, LittleEndian, WriteBytesExt}; -use log::*; use num_derive::{FromPrimitive, ToPrimitive}; use solana_rbpf::{ ebpf::{EbpfError, UserDefinedError}, @@ -156,18 +155,33 @@ pub fn deserialize_parameters( Ok(()) } +macro_rules! log{ + ($logger:ident, $message:expr) => { + if let Ok(mut logger) = $logger.try_borrow_mut() { + if logger.log_enabled() { + logger.log($message); + } + } + }; + ($logger:ident, $fmt:expr, $($arg:tt)*) => { + if let Ok(mut logger) = $logger.try_borrow_mut() { + logger.log(&format!($fmt, $($arg)*)); + } + }; +} + pub fn process_instruction( program_id: &Pubkey, keyed_accounts: &[KeyedAccount], instruction_data: &[u8], invoke_context: &mut dyn InvokeContext, ) -> Result<(), InstructionError> { - solana_logger::setup_with_default("solana=info"); - debug_assert!(bpf_loader::check_id(program_id)); + let logger = invoke_context.get_logger(); + if keyed_accounts.is_empty() { - warn!("No account keys"); + log!(logger, "No account keys"); return Err(InstructionError::NotEnoughAccountKeys); } @@ -187,22 +201,32 @@ pub fn process_instruction( match create_vm(&program_account.data, ¶meter_accounts, invoke_context) { Ok(info) => info, Err(e) => { - warn!("Failed to create BPF VM: {}", e); + log!(logger, "Failed to create BPF VM: {}", e); return Err(BPFLoaderError::VirtualMachineCreationFailed.into()); } }; - info!("Call BPF program {}", program.unsigned_key()); + log!(logger, "Call BPF program {}", program.unsigned_key()); match vm.execute_program(parameter_bytes.as_slice(), &[], &[heap_region]) { Ok(status) => { if status != SUCCESS { let error: InstructionError = status.into(); - warn!("BPF program {} failed: {}", program.unsigned_key(), error); + log!( + logger, + "BPF program {} failed: {}", + program.unsigned_key(), + error + ); return Err(error); } } Err(error) => { - warn!("BPF program {} failed: {}", program.unsigned_key(), error); + log!( + logger, + "BPF program {} failed: {}", + program.unsigned_key(), + error + ); return match error { EbpfError::UserError(BPFError::SyscallError( SyscallError::InstructionError(error), @@ -213,21 +237,25 @@ pub fn process_instruction( } } deserialize_parameters(parameter_accounts, ¶meter_bytes)?; - info!("BPF program {} success", program.unsigned_key()); + log!(logger, "BPF program {} success", program.unsigned_key()); } else if !keyed_accounts.is_empty() { match limited_deserialize(instruction_data)? { LoaderInstruction::Write { offset, bytes } => { let mut keyed_accounts_iter = keyed_accounts.iter(); let program = next_keyed_account(&mut keyed_accounts_iter)?; if program.signer_key().is_none() { - warn!("key[0] did not sign the transaction"); + log!(logger, "key[0] did not sign the transaction"); return Err(InstructionError::MissingRequiredSignature); } let offset = offset as usize; let len = bytes.len(); - trace!("Write: offset={} length={}", offset, len); if program.data_len()? < offset + len { - warn!("Write overflow: {} < {}", program.data_len()?, offset + len); + log!( + logger, + "Write overflow: {} < {}", + program.data_len()?, + offset + len + ); return Err(InstructionError::AccountDataTooSmall); } program.try_account_ref_mut()?.data[offset..offset + len].copy_from_slice(&bytes); @@ -237,17 +265,21 @@ pub fn process_instruction( let program = next_keyed_account(&mut keyed_accounts_iter)?; if program.signer_key().is_none() { - warn!("key[0] did not sign the transaction"); + log!(logger, "key[0] did not sign the transaction"); return Err(InstructionError::MissingRequiredSignature); } if let Err(e) = check_elf(&program.try_account_ref()?.data) { - warn!("{}", e); + log!(logger, "{}", e); return Err(InstructionError::InvalidAccountData); } program.try_account_ref_mut()?.executable = true; - info!("Finalize: account {:?}", program.signer_key().unwrap()); + log!( + logger, + "Finalized account {:?}", + program.signer_key().unwrap() + ); } } } @@ -259,15 +291,18 @@ mod tests { use super::*; use rand::Rng; use solana_sdk::{ - account::Account, entrypoint_native::ProcessInstruction, instruction::CompiledInstruction, - message::Message, rent::Rent, + account::Account, + entrypoint_native::{Logger, ProcessInstruction}, + instruction::CompiledInstruction, + message::Message, + rent::Rent, }; use std::{cell::RefCell, fs::File, io::Read, ops::Range, rc::Rc}; #[derive(Debug, Default)] pub struct MockInvokeContext { key: Pubkey, - pub log: Vec, + mock_logger: MockLogger, } impl InvokeContext for MockInvokeContext { fn push(&mut self, _key: &Pubkey) -> Result<(), InstructionError> { @@ -288,12 +323,20 @@ mod tests { fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &[] } + fn get_logger(&self) -> Rc> { + Rc::new(RefCell::new(self.mock_logger.clone())) + } + } + #[derive(Debug, Default, Clone)] + pub struct MockLogger { + pub log: Rc>>, + } + impl Logger for MockLogger { fn log_enabled(&self) -> bool { true } fn log(&mut self, message: &str) { - info!("[MockInvokeContext::log] {}", message); - self.log.push(message.to_string()); + self.log.borrow_mut().push(message.to_string()); } } @@ -446,8 +489,6 @@ mod tests { #[test] fn test_bpf_loader_invoke_main() { - solana_logger::setup(); - let program_id = Pubkey::new_rand(); let program_key = Pubkey::new_rand(); @@ -560,7 +601,7 @@ mod tests { let mut elf = Vec::new(); file.read_to_end(&mut elf).unwrap(); - info!("mangle the whole file"); + // Mangle the whole file fuzz( &elf, 1_000_000_000, diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 878c27439..e8d6efca6 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -1,6 +1,5 @@ use crate::{alloc, BPFError}; use alloc::Alloc; -use log::*; use solana_rbpf::{ ebpf::{EbpfError, SyscallObject, ELF_INSN_DUMP_OFFSET, MM_HEAP_START}, memory_region::{translate_addr, MemoryRegion}, @@ -13,7 +12,7 @@ use solana_sdk::{ account_info::AccountInfo, bpf_loader, entrypoint::SUCCESS, - entrypoint_native::InvokeContext, + entrypoint_native::{InvokeContext, Logger}, instruction::{AccountMeta, Instruction, InstructionError}, message::Message, program_error::ProgramError, @@ -37,7 +36,7 @@ pub enum SyscallError { InvalidString(Utf8Error, Vec), #[error("BPF program called abort()!")] Abort, - #[error("BPF program Panicked at {0}, {1}:{2}")] + #[error("BPF program Panicked in {0} at {1}:{2}")] Panic(String, u64, u64), #[error("cannot borrow invoke context")] InvokeContextBorrowFailed, @@ -76,46 +75,41 @@ pub fn register_syscalls<'a>( invoke_context: &'a mut dyn InvokeContext, ) -> Result> { // Syscall function common across languages + vm.register_syscall_ex("abort", syscall_abort)?; + vm.register_syscall_ex("sol_panic_", syscall_sol_panic)?; - { - let invoke_context = Rc::new(RefCell::new(invoke_context)); + vm.register_syscall_with_context_ex( + "sol_log_", + Box::new(SyscallLog { + logger: invoke_context.get_logger(), + }), + )?; + vm.register_syscall_with_context_ex( + "sol_log_64_", + Box::new(SyscallLogU64 { + logger: invoke_context.get_logger(), + }), + )?; - 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 - // Cross-program invocation syscalls - vm.register_syscall_with_context_ex( - "sol_invoke_signed_c", - Box::new(SyscallProcessSolInstructionC { - callers_keyed_accounts, - invoke_context: invoke_context.clone(), - }), - )?; - vm.register_syscall_with_context_ex( - "sol_invoke_signed_rust", - Box::new(SyscallProcessInstructionRust { - callers_keyed_accounts, - invoke_context: invoke_context.clone(), - }), - )?; - } + let invoke_context = Rc::new(RefCell::new(invoke_context)); + + vm.register_syscall_with_context_ex( + "sol_invoke_signed_c", + Box::new(SyscallProcessSolInstructionC { + callers_keyed_accounts, + invoke_context: invoke_context.clone(), + }), + )?; + vm.register_syscall_with_context_ex( + "sol_invoke_signed_rust", + Box::new(SyscallProcessInstructionRust { + callers_keyed_accounts, + invoke_context: invoke_context.clone(), + }), + )?; // Memory allocator let heap = vec![0_u8; DEFAULT_HEAP_SIZE]; @@ -232,49 +226,25 @@ pub fn syscall_abort( /// Panic syscall function, called when the BPF program calls 'sol_panic_()` /// Causes the BPF program to be halted immediately -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()) - }) - } +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, &mut |string: &str| { + Err(SyscallError::Panic(string.to_string(), line, column).into()) + }) } /// Log a user's info message -pub struct SyscallLog<'a> { - invoke_context: Rc>, +pub struct SyscallLog { + logger: 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> { +impl SyscallObject for SyscallLog { fn call( &mut self, addr: u64, @@ -285,10 +255,13 @@ impl<'a> SyscallObject for SyscallLog<'a> { ro_regions: &[MemoryRegion], _rw_regions: &[MemoryRegion], ) -> Result> { - let mut invoke_context = self.get_context_mut()?; - if invoke_context.log_enabled() { + let mut logger = self + .logger + .try_borrow_mut() + .map_err(|_| SyscallError::InvokeContextBorrowFailed)?; + if logger.log_enabled() { translate_string_and_do(addr, len, ro_regions, &mut |string: &str| { - invoke_context.log(string); + logger.log(&format!("Program log: {}", string)); Ok(0) })?; } @@ -297,17 +270,10 @@ impl<'a> SyscallObject for SyscallLog<'a> { } /// Log 5 64-bit values -pub struct SyscallLogU64<'a> { - invoke_context: Rc>, +pub struct SyscallLogU64 { + logger: 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> { +impl SyscallObject for SyscallLogU64 { fn call( &mut self, arg1: u64, @@ -318,10 +284,13 @@ impl<'a> SyscallObject for SyscallLogU64<'a> { _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}", + let mut logger = self + .logger + .try_borrow_mut() + .map_err(|_| SyscallError::InvokeContextBorrowFailed)?; + if logger.log_enabled() { + logger.log(&format!( + "Program log: {:#x}, {:#x}, {:#x}, {:#x}, {:#x}", arg1, arg2, arg3, arg4, arg5 )); } @@ -863,8 +832,7 @@ fn call<'a>( #[cfg(test)] mod tests { use super::*; - use crate::tests::MockInvokeContext; - use solana_sdk::entrypoint_native::InvokeContext; + use crate::tests::MockLogger; #[test] fn test_translate() { @@ -988,38 +956,23 @@ mod tests { #[should_panic(expected = "UserError(SyscallError(Panic(\"Gaggablaghblagh!\", 42, 84)))")] fn test_syscall_sol_panic() { let string = "Gaggablaghblagh!"; - - 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 addr = string.as_ptr() as *const _ as u64; + let ro_region = MemoryRegion { + addr_host: addr, + addr_vm: 100, + len: string.len() as u64, }; - assert_eq!(mock_invoke_context.log.len(), 1); - assert_eq!( - mock_invoke_context.log[0], - "panicked at \'Gaggablaghblagh!\' on 42:84" - ); - - result.unwrap(); + let rw_region = MemoryRegion::default(); + syscall_sol_panic( + 100, + string.len() as u64, + 42, + 84, + 0, + &[ro_region], + &[rw_region], + ) + .unwrap(); } #[test] @@ -1033,50 +986,47 @@ mod tests { }]; let rw_regions = &[MemoryRegion::default()]; - 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)), - }; + let log = Rc::new(RefCell::new(vec![])); + let mock_logger = MockLogger { log: log.clone() }; + let logger: Rc> = Rc::new(RefCell::new(mock_logger)); + let mut syscall_sol_log = SyscallLog { logger }; - 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, 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!"); + syscall_sol_log + .call( + 100, + string.len() as u64 * 2, // AccessViolation + 0, + 0, + 0, + ro_regions, + rw_regions, + ) + .unwrap_err(); + + assert_eq!(log.borrow().len(), 1); + assert_eq!(log.borrow()[0], "Program log: Gaggablaghblagh!"); } #[test] fn test_syscall_sol_log_u64() { - 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 log = Rc::new(RefCell::new(vec![])); + let mock_logger = MockLogger { log: log.clone() }; + let mut syscall_sol_log_u64 = SyscallLogU64 { + logger: Rc::new(RefCell::new(mock_logger)), + }; + let ro_regions = &[MemoryRegion::default()]; + let rw_regions = &[MemoryRegion::default()]; - 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"); + syscall_sol_log_u64 + .call(1, 2, 3, 4, 5, ro_regions, rw_regions) + .unwrap(); + + assert_eq!(log.borrow().len(), 1); + assert_eq!(log.borrow()[0], "Program log: 0x1, 0x2, 0x3, 0x4, 0x5"); } #[test] diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index d0fab2f0c..704b4e4db 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -1348,7 +1348,7 @@ impl Bank { &self, batch: &TransactionBatch, max_age: usize, - log_collector: Option<&LogCollector>, + log_collector: Option>, ) -> ( Vec<(Result, Option)>, Vec, @@ -1408,7 +1408,7 @@ impl Bank { &loader_refcells, &account_refcells, &self.rent_collector, - log_collector, + log_collector.clone(), ); Self::refcells_to_accounts( diff --git a/runtime/src/log_collector.rs b/runtime/src/log_collector.rs index 0d0710e70..dda5bf36b 100644 --- a/runtime/src/log_collector.rs +++ b/runtime/src/log_collector.rs @@ -9,8 +9,9 @@ impl LogCollector { pub fn log(&self, message: &str) { self.messages.borrow_mut().push(message.to_string()) } - - pub fn output(self) -> Vec { +} +impl Into> for LogCollector { + fn into(self) -> Vec { self.messages.into_inner() } } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 737743cc0..575449905 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -6,7 +6,7 @@ use serde::{Deserialize, Serialize}; use solana_sdk::{ account::{create_keyed_readonly_accounts, Account, KeyedAccount}, clock::Epoch, - entrypoint_native::{InvokeContext, ProcessInstruction}, + entrypoint_native::{InvokeContext, Logger, ProcessInstruction}, instruction::{CompiledInstruction, InstructionError}, message::Message, native_loader, @@ -154,23 +154,21 @@ impl PreAccount { } } -#[derive(Default)] -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>, +pub struct ThisInvokeContext { + program_ids: Vec, + rent: Rent, + pre_accounts: Vec, + programs: Vec<(Pubkey, ProcessInstruction)>, + logger: Rc>, } - -impl<'a> ThisInvokeContext<'a> { +impl ThisInvokeContext { 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>, + log_collector: Option>, ) -> Self { let mut program_ids = Vec::with_capacity(Self::MAX_INVOCATION_DEPTH); program_ids.push(*program_id); @@ -179,12 +177,11 @@ impl<'a> ThisInvokeContext<'a> { rent, pre_accounts, programs, - log_collector, + logger: Rc::new(RefCell::new(ThisLogger { log_collector })), } } } - -impl<'a> InvokeContext for ThisInvokeContext<'a> { +impl InvokeContext for ThisInvokeContext { fn push(&mut self, key: &Pubkey) -> Result<(), InstructionError> { if self.program_ids.len() >= Self::MAX_INVOCATION_DEPTH { return Err(InstructionError::CallDepth); @@ -222,18 +219,23 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { .last() .ok_or(InstructionError::GenericError) } - fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)] { &self.programs } - + fn get_logger(&self) -> Rc> { + self.logger.clone() + } +} +pub struct ThisLogger { + log_collector: Option>, +} +impl Logger for ThisLogger { 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 { + if let Some(log_collector) = &self.log_collector { log_collector.log(message); } } @@ -502,14 +504,14 @@ impl MessageProcessor { executable_accounts: &[(Pubkey, RefCell)], accounts: &[Rc>], rent_collector: &RentCollector, - log_collector: Option<&LogCollector>, + log_collector: Option>, ) -> Result<(), InstructionError> { let pre_accounts = Self::create_pre_accounts(message, instruction, accounts); let mut invoke_context = ThisInvokeContext::new( instruction.program_id(&message.account_keys), rent_collector.rent, pre_accounts, - self.programs.clone(), + self.programs.clone(), // get rid of clone log_collector, ); let keyed_accounts = @@ -535,7 +537,7 @@ impl MessageProcessor { loaders: &[Vec<(Pubkey, RefCell)>], accounts: &[Rc>], rent_collector: &RentCollector, - log_collector: Option<&LogCollector>, + log_collector: Option>, ) -> Result<(), TransactionError> { for (instruction_index, instruction) in message.instructions.iter().enumerate() { self.execute_instruction( @@ -544,7 +546,7 @@ impl MessageProcessor { &loaders[instruction_index], accounts, rent_collector, - log_collector, + log_collector.clone(), ) .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } diff --git a/sdk/src/entrypoint_native.rs b/sdk/src/entrypoint_native.rs index db07497ca..04ecd3b0d 100644 --- a/sdk/src/entrypoint_native.rs +++ b/sdk/src/entrypoint_native.rs @@ -165,7 +165,12 @@ pub trait InvokeContext { fn get_caller(&self) -> Result<&Pubkey, InstructionError>; /// Get a list of built-in programs fn get_programs(&self) -> &[(Pubkey, ProcessInstruction)]; - /// Check if logging is enabled + /// Get this invocation's logger + fn get_logger(&self) -> Rc>; +} + +/// Log messages +pub trait Logger { fn log_enabled(&self) -> bool; /// Log a message fn log(&mut self, message: &str);