Log more info on runtime account verification errors (#17861)

runtime/src/message_processor.rs

@@ -10,7 +10,7 @@ use solana_sdk::{
     account_utils::StateMut,
     bpf_loader_upgradeable::{self, UpgradeableLoaderState},
     feature_set::{demote_sysvar_write_locks, instructions_sysvar_enabled, FeatureSet},
-    ic_msg,
+    ic_logger_msg, ic_msg,
     instruction::{CompiledInstruction, Instruction, InstructionError},
     keyed_account::{create_keyed_accounts_unified, keyed_account_at_index, KeyedAccount},
     message::Message,
@@ -403,6 +403,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
             .invoke_stack
             .last()
             .ok_or(InstructionError::CallDepth)?;
+        let logger = self.get_logger();
         MessageProcessor::verify_and_update(
             message,
             instruction,
@@ -413,6 +414,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
             caller_write_privileges,
             &mut self.timings,
             self.feature_set.is_active(&demote_sysvar_write_locks::id()),
+            logger,
         )
     }
     fn get_caller(&self) -> Result<&Pubkey, InstructionError> {
@@ -1015,6 +1017,7 @@ impl MessageProcessor {
         rent: &Rent,
         timings: &mut ExecuteDetailsTimings,
         demote_sysvar_write_locks: bool,
+        logger: Rc<RefCell<dyn Logger>>,
     ) -> Result<(), InstructionError> {
         // Verify all executable accounts have zero outstanding refs
         Self::verify_account_references(executable_accounts)?;
@@ -1031,14 +1034,24 @@ impl MessageProcessor {
                         .map_err(|_| InstructionError::AccountBorrowOutstanding)?;
                 }
                 let account = accounts[account_index].borrow();
-                pre_accounts[unique_index].verify(
-                    &program_id,
-                    message.is_writable(account_index, demote_sysvar_write_locks),
-                    rent,
-                    &account,
-                    timings,
-                    true,
-                )?;
+                pre_accounts[unique_index]
+                    .verify(
+                        &program_id,
+                        message.is_writable(account_index, demote_sysvar_write_locks),
+                        rent,
+                        &account,
+                        timings,
+                        true,
+                    )
+                    .map_err(|err| {
+                        ic_logger_msg!(
+                            logger,
+                            "failed to verify account {}: {}",
+                            pre_accounts[unique_index].key,
+                            err
+                        );
+                        err
+                    })?;
                 pre_sum += u128::from(pre_accounts[unique_index].lamports());
                 post_sum += u128::from(account.lamports());
                 Ok(())
@@ -1054,6 +1067,7 @@ impl MessageProcessor {
     }
 
     /// Verify the results of a cross-program instruction
+    #[allow(clippy::too_many_arguments)]
     fn verify_and_update(
         message: &Message,
         instruction: &CompiledInstruction,
@@ -1064,6 +1078,7 @@ impl MessageProcessor {
         caller_write_privileges: Option<&[bool]>,
         timings: &mut ExecuteDetailsTimings,
         demote_sysvar_write_locks: bool,
+        logger: Rc<RefCell<dyn Logger>>,
     ) -> Result<(), InstructionError> {
         // Verify the per-account instruction results
         let (mut pre_sum, mut post_sum) = (0_u128, 0_u128);
@@ -1086,14 +1101,12 @@ impl MessageProcessor {
                                 .map_err(|_| InstructionError::AccountBorrowOutstanding)?;
                         }
                         let account = account.borrow();
-                        pre_account.verify(
-                            &program_id,
-                            is_writable,
-                            &rent,
-                            &account,
-                            timings,
-                            false,
-                        )?;
+                        pre_account
+                            .verify(&program_id, is_writable, &rent, &account, timings, false)
+                            .map_err(|err| {
+                                ic_logger_msg!(logger, "failed to verify account {}: {}", key, err);
+                                err
+                            })?;
                         pre_sum += u128::from(pre_account.lamports());
                         post_sum += u128::from(account.lamports());
                         if is_writable && !account.executable() {
@@ -1182,6 +1195,7 @@ impl MessageProcessor {
             &rent_collector.rent,
             timings,
             demote_sysvar_write_locks,
+            invoke_context.get_logger(),
         )?;
 
         timings.accumulate(&invoke_context.timings);