Add stable program logging for BPF and native programs

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

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",
         );

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!(
+                        stable_log::program_failure(&logger, program.unsigned_key(), &error);
-                            logger,
-                            "BPF program {} failed: {}",
-                            program.unsigned_key(),
-                            error
-                        );
                         return Err(error);
                     }
                 }
                 Err(error) => {
-                    log!(
+                    let error = match error {
-                        logger,
-                        "BPF program {} failed: {}",
-                        program.unsigned_key(),
-                        error
-                    );
-                    return match error {
                         EbpfError::UserError(BPFError::SyscallError(
                             SyscallError::InstructionError(error),
-                        )) => Err(error),
+                        )) => error,
-                        _ => Err(BPFLoaderError::VirtualMachineFailedToRunProgram.into()),
+                        _ => BPFLoaderError::VirtualMachineFailedToRunProgram.into(),
                     };
+
+                    stable_log::program_failure(&logger, program.unsigned_key(), &error);
+                    return Err(error);
                 }
             }
         }
         deserialize_parameters(program_id, parameter_accounts, &parameter_bytes)?;
-        log!(logger, "BPF program {} success", program.unsigned_key());
+        stable_log::program_success(&logger, program.unsigned_key());
         Ok(())
     }
 }

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<BPFError> for SyscallLog<'a> {
         memory_mapping: &MemoryMapping,
     ) -> Result<u64, EbpfError<BPFError>> {
         self.compute_meter.consume(self.cost)?;
-        let logger = self
+        translate_string_and_do(
-            .logger
+            memory_mapping,
-            .try_borrow_mut()
+            AccessType::Load,
-            .map_err(|_| SyscallError::InvokeContextBorrowFailed)?;
+            addr,
-        if logger.log_enabled() {
+            len,
-            translate_string_and_do(
+            &self.loader_id,
-                memory_mapping,
+            &mut |string: &str| {
-                AccessType::Load,
+                stable_log::program_log(&self.logger, string);
-                addr,
+                Ok(0)
-                len,
+            },
-                &self.loader_id,
+        )?;
-                &mut |string: &str| {
-                    logger.log(&format!("Program log: {}", string));
-                    Ok(0)
-                },
-            )?;
-        }
         Ok(0)
     }
 }
@@ -407,16 +401,13 @@ impl SyscallObject<BPFError> for SyscallLogU64 {
         _memory_mapping: &MemoryMapping,
     ) -> Result<u64, EbpfError<BPFError>> {
         self.compute_meter.consume(self.cost)?;
-        let logger = self
+        stable_log::program_log(
-            .logger
+            &self.logger,
-            .try_borrow_mut()
+            &format!(
-            .map_err(|_| SyscallError::InvokeContextBorrowFailed)?;
+                "{:#x}, {:#x}, {:#x}, {:#x}, {:#x}",
-        if logger.log_enabled() {
-            logger.log(&format!(
-                "Program log: {:#x}, {:#x}, {:#x}, {:#x}, {:#x}",
                 arg1, arg2, arg3, arg4, arg5
-            ));
+            ),
-        }
+        );
         Ok(0)
     }
 }
@@ -470,20 +461,14 @@ impl<'a> SyscallObject<BPFError> for SyscallLogPubkey<'a> {
         memory_mapping: &MemoryMapping,
     ) -> Result<u64, EbpfError<BPFError>> {
         self.compute_meter.consume(self.cost)?;
-        let logger = self
+        let pubkey = translate_type!(
-            .logger
+            memory_mapping,
-            .try_borrow_mut()
+            AccessType::Load,
-            .map_err(|_| SyscallError::InvokeContextBorrowFailed)?;
+            pubkey_addr,
-        if logger.log_enabled() {
+            Pubkey,
-            let pubkey = translate_type!(
+            self.loader_id
-                memory_mapping,
+        )?;
-                AccessType::Load,
+        stable_log::program_log(&self.logger, &pubkey.to_string());
-                pubkey_addr,
-                Pubkey,
-                self.loader_id
-            )?;
-            logger.log(&format!("Program log: {}", pubkey));
-        }
         Ok(0)
     }
 }

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

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<Builtin> {
@@ -10,24 +53,26 @@ fn genesis_builtins() -> Vec<Builtin> {
         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),
         ),
     ]
 }

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

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 <address> invoke [<depth>]"
+    pub fn program_invoke(
+        logger: &Rc<RefCell<dyn Logger>>,
+        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: <program-generated output>"
+    /// That is, any program-generated output is guaranteed to be prefixed by "Program log: "
+    pub fn program_log(logger: &Rc<RefCell<dyn Logger>>, 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 <address> success"
+    pub fn program_success(logger: &Rc<RefCell<dyn Logger>>, 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 <address> failed: <program error details>"
+    pub fn program_failure(
+        logger: &Rc<RefCell<dyn Logger>>,
+        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,

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