RPC simulateTransaction endpoint now returns program log output (#10432)

client/src/rpc_client.rs

@@ -129,7 +129,7 @@ impl RpcClient {
         &self,
         transaction: &Transaction,
         sig_verify: bool,
-    ) -> RpcResult<TransactionStatus> {
+    ) -> RpcResult<RpcSimulateTransactionResult> {
         let serialized_encoded = bs58::encode(serialize(transaction).unwrap()).into_string();
         self.send(
             RpcRequest::SimulateTransaction,

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<TransactionError>,
+    pub logs: Option<Vec<String>>,
+}
+
 #[derive(Serialize, Deserialize, Clone, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct RpcStorageTurn {

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();

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<Signature> {
 }
 
 /// 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<String>) {
     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);
+        bank.load_and_execute_transactions(
-    executed[0].0.clone().map(|_| ())
+            &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<RpcSimulateTransactionConfig>,
-    ) -> RpcResponse<TransactionStatus>;
+    ) -> RpcResponse<RpcSimulateTransactionResult>;
 
     #[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<RpcSimulateTransactionConfig>,
-    ) -> RpcResponse<TransactionStatus> {
+    ) -> RpcResponse<RpcSimulateTransactionResult> {
         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)?;
-
+        let logs = if result.is_ok() {
-        if result.is_ok() {
+            let sim_result = run_transaction_simulation(&bank, transaction);
-            result = run_transaction_simulation(&bank, transaction);
+            result = sim_result.0;
-        }
+            Some(sim_result.1)
+        } else {
+            None
+        };
 
         new_response(
             &bank,
-            TransactionStatus {
+            RpcSimulateTransactionResult {
-                slot: bank.slot(),
-                confirmations: Some(0),
-                status: result.clone(),
                 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,
         });

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: <object | null>` - 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 | null>` - 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:
 

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) {}
 }

programs/bpf_loader/src/lib.rs

@@ -267,6 +267,7 @@ mod tests {
     #[derive(Debug, Default)]
     pub struct MockInvokeContext {
         key: Pubkey,
+        pub log: Vec<String>,
     }
     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]

programs/bpf_loader/src/syscalls.rs

@@ -77,13 +77,30 @@ pub fn register_syscalls<'a>(
 ) -> Result<MemoryRegion, EbpfError<BPFError>> {
     // 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<u64, EbpfError<BPFError>>,
+    work: &mut dyn FnMut(&str) -> Result<u64, EbpfError<BPFError>>,
 ) -> Result<u64, EbpfError<BPFError>> {
     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(
+pub struct SyscallPanic<'a> {
-    file: u64,
+    invoke_context: Rc<RefCell<&'a mut dyn InvokeContext>>,
-    len: u64,
+}
-    line: u64,
+impl<'a> SyscallPanic<'a> {
-    column: u64,
+    fn get_context_mut(&self) -> Result<RefMut<&'a mut dyn InvokeContext>, EbpfError<BPFError>> {
-    _arg5: u64,
+        self.invoke_context
-    ro_regions: &[MemoryRegion],
+            .try_borrow_mut()
-    _rw_regions: &[MemoryRegion],
+            .map_err(|_| SyscallError::InvokeContextBorrowFailed.into())
-) -> Result<u64, EbpfError<BPFError>> {
+    }
-    translate_string_and_do(file, len, ro_regions, &|string: &str| {
+}
-        Err(SyscallError::Panic(string.to_string(), line, column).into())
+impl<'a> SyscallObject<BPFError> for SyscallPanic<'a> {
-    })
+    fn call(
+        &mut self,
+        file: u64,
+        len: u64,
+        line: u64,
+        column: u64,
+        _arg5: u64,
+        ro_regions: &[MemoryRegion],
+        _rw_regions: &[MemoryRegion],
+    ) -> Result<u64, EbpfError<BPFError>> {
+        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(
+pub struct SyscallLog<'a> {
-    addr: u64,
+    invoke_context: Rc<RefCell<&'a mut dyn InvokeContext>>,
-    len: u64,
+}
-    _arg3: u64,
+impl<'a> SyscallLog<'a> {
-    _arg4: u64,
+    fn get_context_mut(&self) -> Result<RefMut<&'a mut dyn InvokeContext>, EbpfError<BPFError>> {
-    _arg5: u64,
+        self.invoke_context
-    ro_regions: &[MemoryRegion],
+            .try_borrow_mut()
-    _rw_regions: &[MemoryRegion],
+            .map_err(|_| SyscallError::InvokeContextBorrowFailed.into())
-) -> Result<u64, EbpfError<BPFError>> {
+    }
-    if log_enabled!(log::Level::Info) {
+}
-        translate_string_and_do(addr, len, ro_regions, &|string: &str| {
+impl<'a> SyscallObject<BPFError> for SyscallLog<'a> {
-            info!("info!: {}", string);
+    fn call(
-            Ok(0)
+        &mut self,
-        })?;
+        addr: u64,
+        len: u64,
+        _arg3: u64,
+        _arg4: u64,
+        _arg5: u64,
+        ro_regions: &[MemoryRegion],
+        _rw_regions: &[MemoryRegion],
+    ) -> Result<u64, EbpfError<BPFError>> {
+        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(
+pub struct SyscallLogU64<'a> {
-    arg1: u64,
+    invoke_context: Rc<RefCell<&'a mut dyn InvokeContext>>,
-    arg2: u64,
+}
-    arg3: u64,
+impl<'a> SyscallLogU64<'a> {
-    arg4: u64,
+    fn get_context_mut(&self) -> Result<RefMut<&'a mut dyn InvokeContext>, EbpfError<BPFError>> {
-    arg5: u64,
+        self.invoke_context
-    _ro_regions: &[MemoryRegion],
+            .try_borrow_mut()
-    _rw_regions: &[MemoryRegion],
+            .map_err(|_| SyscallError::InvokeContextBorrowFailed.into())
-) -> Result<u64, EbpfError<BPFError>> {
+    }
-    if log_enabled!(log::Level::Info) {
+}
-        info!(
+impl<'a> SyscallObject<BPFError> for SyscallLogU64<'a> {
-            "info!: {:#x}, {:#x}, {:#x}, {:#x}, {:#x}",
+    fn call(
-            arg1, arg2, arg3, arg4, arg5
+        &mut self,
-        );
+        arg1: u64,
+        arg2: u64,
+        arg3: u64,
+        arg4: u64,
+        arg5: u64,
+        _ro_regions: &[MemoryRegion],
+        _rw_regions: &[MemoryRegion],
+    ) -> Result<u64, EbpfError<BPFError>> {
+        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, &regions, &|string: &str| {
+            translate_string_and_do(100, string.len() as u64, &regions, &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 {
+        let mut mock_invoke_context = MockInvokeContext::default();
-            addr_host: addr,
+        let result = {
-            addr_vm: 100,
+            let invoke_context: &mut dyn InvokeContext = &mut mock_invoke_context;
-            len: string.len() as u64,
+            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();
+        assert_eq!(mock_invoke_context.log.len(), 1);
-        syscall_sol_panic(
+        assert_eq!(
-            100,
+            mock_invoke_context.log[0],
-            string.len() as u64,
+            "panicked at \'Gaggablaghblagh!\' on 42:84"
-            42,
+        );
-            84,
+
-            0,
+        result.unwrap();
-            &[ro_region],
-            &[rw_region],
-        )
-        .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();
+        let mut mock_invoke_context = MockInvokeContext::default();
-        solana_logger::setup_with_default("solana=info");
+        {
-        syscall_sol_log(
+            let invoke_context: &mut dyn InvokeContext = &mut mock_invoke_context;
-            100,
+            let mut syscall_sol_log = SyscallLog {
-            string.len() as u64 * 2,
+                invoke_context: Rc::new(RefCell::new(invoke_context)),
-            0,
+            };
-            0,
+
-            0,
+            syscall_sol_log
-            ro_regions,
+                .call(100, string.len() as u64, 0, 0, 0, ro_regions, rw_regions)
-            rw_regions,
+                .unwrap();
-        )
+
-        .unwrap_err();
+            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 ro_regions = &[MemoryRegion::default()];
-        let rw_regions = &[MemoryRegion::default()];
+            let rw_regions = &[MemoryRegion::default()];
-        syscall_sol_log_u64(1, 2, 3, 4, 5, ro_regions, rw_regions).unwrap();
+            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]

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<TransactionLoadResult>, Option<HashAgeKind>)>,
         Vec<TransactionProcessResult>,
@@ -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(),

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;

runtime/src/log_collector.rs

@@ -0,0 +1,16 @@
+use std::cell::RefCell;
+
+#[derive(Default)]
+pub struct LogCollector {
+    messages: RefCell<Vec<String>>,
+}
+
+impl LogCollector {
+    pub fn log(&self, message: &str) {
+        self.messages.borrow_mut().push(message.to_string())
+    }
+
+    pub fn output(self) -> Vec<String> {
+        self.messages.into_inner()
+    }
+}

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<Pubkey>,
     pub rent: Rent,
     pub pre_accounts: Vec<PreAccount>,
     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<PreAccount>,
         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<Account>)],
         accounts: &[Rc<RefCell<Account>>],
         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<Account>)>],
         accounts: &[Rc<RefCell<Account>>],
         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),

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);
 }