From b9791273ddb2eb8e8b1035095445b364c4d9a6f4 Mon Sep 17 00:00:00 2001 From: ananas-block Date: Wed, 6 Aug 2025 09:46:17 +0200 Subject: [PATCH 1/3] feat: format tx logs in light program test --- CLAUDE.md | 29 + Cargo.lock | 6 + Cargo.toml | 1 + program-tests/registry-test/tests/tests.rs | 1 + sdk-libs/program-test/Cargo.toml | 6 + sdk-libs/program-test/src/lib.rs | 1 + sdk-libs/program-test/src/logging/config.rs | 109 ++ sdk-libs/program-test/src/logging/decoder.rs | 979 +++++++++++++ .../program-test/src/logging/decoder.rs:70:15 | 0 .../src/logging/decoder.rs:946:15 | 0 .../program-test/src/logging/formatter.rs | 1235 +++++++++++++++++ .../src/logging/formatter.rs:1218:19 | 0 sdk-libs/program-test/src/logging/mod.rs | 195 +++ sdk-libs/program-test/src/logging/types.rs | 480 +++++++ .../program-test/src/logging/types.rs:473:15 | 0 .../program-test/src/program_test/config.rs | 36 +- .../src/program_test/light_program_test.rs | 2 + sdk-libs/program-test/src/program_test/rpc.rs | 101 +- 18 files changed, 3159 insertions(+), 22 deletions(-) create mode 100644 CLAUDE.md create mode 100644 sdk-libs/program-test/src/logging/config.rs create mode 100644 sdk-libs/program-test/src/logging/decoder.rs create mode 100644 sdk-libs/program-test/src/logging/decoder.rs:70:15 create mode 100644 sdk-libs/program-test/src/logging/decoder.rs:946:15 create mode 100644 sdk-libs/program-test/src/logging/formatter.rs create mode 100644 sdk-libs/program-test/src/logging/formatter.rs:1218:19 create mode 100644 sdk-libs/program-test/src/logging/mod.rs create mode 100644 sdk-libs/program-test/src/logging/types.rs create mode 100644 sdk-libs/program-test/src/logging/types.rs:473:15 diff --git a/CLAUDE.md b/CLAUDE.md new file mode 100644 index 0000000000..1ba7ab99e5 --- /dev/null +++ b/CLAUDE.md @@ -0,0 +1,29 @@ +# Light Protocol Enhanced Logging + +## Transaction Log File + +The light-program-test library automatically creates detailed transaction logs in: +``` +target/light_program_test.log +``` + +### Features + +- **Always enabled**: Logs are written to file regardless of environment variables +- **Clean format**: Plain text without ANSI color codes for easy reading and processing +- **Session-based**: Each test session starts with a timestamp header, transactions append to the same file +- **Comprehensive details**: Includes transaction signatures, fees, compute usage, instruction hierarchies, Light Protocol instruction parsing, and compressed account information + +### Configuration + +Enhanced logging is enabled by default. To disable: +```rust +let mut config = ProgramTestConfig::default(); +config.enhanced_logging.enabled = false; +``` + +Console output requires `RUST_BACKTRACE` environment variable and can be controlled separately from file logging. + +### Log File Location + +The log file is automatically placed in the cargo workspace target directory, making it consistent across different test environments and working directories. \ No newline at end of file diff --git a/Cargo.lock b/Cargo.lock index b6bf893a0f..4ad0ef81bd 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3551,6 +3551,7 @@ dependencies = [ "anchor-lang", "async-trait", "borsh 0.10.4", + "bs58", "bytemuck", "light-batched-merkle-tree", "light-client", @@ -3565,6 +3566,7 @@ dependencies = [ "light-prover-client", "light-registry", "light-sdk", + "light-sdk-types", "litesvm", "log", "num-bigint 0.4.6", @@ -3572,6 +3574,8 @@ dependencies = [ "photon-api", "rand 0.8.5", "reqwest 0.12.20", + "serde", + "serde_json", "solana-account", "solana-banks-client", "solana-compute-budget", @@ -3580,7 +3584,9 @@ dependencies = [ "solana-rpc-client-api", "solana-sdk", "solana-transaction", + "solana-transaction-status", "solana-transaction-status-client-types", + "tabled", "tokio", ] diff --git a/Cargo.toml b/Cargo.toml index ae4693fe8a..9aa8fe4ed4 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -197,6 +197,7 @@ arrayvec = "0.7" # Math and crypto num-bigint = "0.4.6" +tabled = "0.20" num-traits = "0.2.19" zerocopy = { version = "0.8.25" } base64 = "0.13" diff --git a/program-tests/registry-test/tests/tests.rs b/program-tests/registry-test/tests/tests.rs index 4b4765ec1e..f363c5c85e 100644 --- a/program-tests/registry-test/tests/tests.rs +++ b/program-tests/registry-test/tests/tests.rs @@ -193,6 +193,7 @@ async fn test_initialize_protocol_config() { test_accounts: TestAccounts::get_program_test_test_accounts(), payer, config: ProgramTestConfig::default(), + transaction_counter: 0, }; let payer = rpc.get_payer().insecure_clone(); diff --git a/sdk-libs/program-test/Cargo.toml b/sdk-libs/program-test/Cargo.toml index c9a826ebc7..f7745c9b7a 100644 --- a/sdk-libs/program-test/Cargo.toml +++ b/sdk-libs/program-test/Cargo.toml @@ -51,3 +51,9 @@ solana-account = { workspace = true } solana-compute-budget = { workspace = true } rand = { workspace = true } bytemuck = { workspace = true } +serde = { workspace = true } +serde_json = { workspace = true } +solana-transaction-status = { workspace = true } +bs58 = { workspace = true } +light-sdk-types = { workspace = true } +tabled = { workspace = true } diff --git a/sdk-libs/program-test/src/lib.rs b/sdk-libs/program-test/src/lib.rs index e1825673de..c36f8a52d3 100644 --- a/sdk-libs/program-test/src/lib.rs +++ b/sdk-libs/program-test/src/lib.rs @@ -114,6 +114,7 @@ pub mod accounts; pub mod indexer; +pub mod logging; pub mod program_test; pub mod utils; diff --git a/sdk-libs/program-test/src/logging/config.rs b/sdk-libs/program-test/src/logging/config.rs new file mode 100644 index 0000000000..3538cf3dbb --- /dev/null +++ b/sdk-libs/program-test/src/logging/config.rs @@ -0,0 +1,109 @@ +//! Configuration types for enhanced logging + +use serde::{Deserialize, Serialize}; + +/// Configuration for enhanced transaction logging +#[derive(Debug, Clone, Serialize, Deserialize)] +pub struct EnhancedLoggingConfig { + /// Whether enhanced logging is enabled + pub enabled: bool, + /// Whether to log events to console (file logging is always enabled when enhanced_logging.enabled = true) + pub log_events: bool, + /// Level of detail in logs + pub verbosity: LogVerbosity, + /// Show account changes before/after transaction + pub show_account_changes: bool, + /// Decode Light Protocol specific instructions + pub decode_light_instructions: bool, + /// Show compute units consumed per instruction + pub show_compute_units: bool, + /// Use ANSI colors in output + pub use_colors: bool, + /// Maximum number of inner instruction levels to display + pub max_inner_instruction_depth: usize, + /// Show instruction data for account compression program + pub show_compression_instruction_data: bool, +} + +impl Default for EnhancedLoggingConfig { + fn default() -> Self { + Self { + enabled: true, // Always enabled for processing + log_events: false, // Don't log by default + verbosity: LogVerbosity::Standard, + show_account_changes: true, + decode_light_instructions: true, + show_compute_units: true, + use_colors: true, + max_inner_instruction_depth: 60, + show_compression_instruction_data: false, + } + } +} + +/// Verbosity levels for transaction logging +#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)] +pub enum LogVerbosity { + /// Only instruction hierarchy and status + Brief, + /// + account changes and basic instruction info + Standard, + /// + parsed instruction data when available + Detailed, + /// + raw instruction data and internal debugging info + Full, +} + +impl EnhancedLoggingConfig { + /// Create config optimized for debugging + pub fn debug() -> Self { + Self { + enabled: true, + log_events: true, // Enable logging for debug mode + verbosity: LogVerbosity::Full, + show_account_changes: true, + decode_light_instructions: true, + show_compute_units: true, + use_colors: true, + max_inner_instruction_depth: 60, + show_compression_instruction_data: false, + } + } + + /// Create config optimized for CI/production + pub fn minimal() -> Self { + Self { + enabled: true, + log_events: false, // Don't log for minimal config + verbosity: LogVerbosity::Brief, + show_account_changes: false, + decode_light_instructions: false, + show_compute_units: false, + use_colors: false, + max_inner_instruction_depth: 60, + show_compression_instruction_data: false, + } + } + + /// Create config based on environment - always enabled, debug level when RUST_BACKTRACE is set + pub fn from_env() -> Self { + if std::env::var("RUST_BACKTRACE").is_ok() { + Self::debug() + } else { + // Always enabled but with standard verbosity when backtrace is not set + Self::default() + } + } + + /// Enable event logging with current settings + pub fn with_logging(mut self) -> Self { + self.log_events = true; + self + } + + /// Disable event logging + pub fn without_logging(mut self) -> Self { + self.log_events = false; + self + } +} diff --git a/sdk-libs/program-test/src/logging/decoder.rs b/sdk-libs/program-test/src/logging/decoder.rs new file mode 100644 index 0000000000..c7c98a29bc --- /dev/null +++ b/sdk-libs/program-test/src/logging/decoder.rs @@ -0,0 +1,979 @@ +//! Instruction decoder for Light Protocol and common Solana programs + +use borsh::BorshDeserialize; +use light_compressed_account::instruction_data::{ + data::InstructionDataInvoke, invoke_cpi::InstructionDataInvokeCpi, + with_account_info::InstructionDataInvokeCpiWithAccountInfo, + with_readonly::InstructionDataInvokeCpiWithReadOnly, +}; +use solana_sdk::{instruction::AccountMeta, pubkey::Pubkey, system_program}; + +use super::types::ParsedInstructionData; + +/// Helper to resolve merkle tree and queue pubkeys from instruction accounts +/// For InvokeCpi instructions, tree accounts start 2 positions after the system program +fn resolve_tree_and_queue_pubkeys( + accounts: &[AccountMeta], + merkle_tree_index: Option, + nullifier_queue_index: Option, +) -> (Option, Option) { + let mut tree_pubkey = None; + let mut queue_pubkey = None; + + // Find the system program account position + let mut system_program_pos = None; + for (i, account) in accounts.iter().enumerate() { + if account.pubkey == system_program::ID { + system_program_pos = Some(i); + break; + } + } + + if let Some(system_pos) = system_program_pos { + // Tree accounts start 2 positions after system program + let tree_accounts_start = system_pos + 2; + + if let Some(tree_idx) = merkle_tree_index { + let tree_account_pos = tree_accounts_start + tree_idx as usize; + if tree_account_pos < accounts.len() { + tree_pubkey = Some(accounts[tree_account_pos].pubkey); + } + } + + if let Some(queue_idx) = nullifier_queue_index { + let queue_account_pos = tree_accounts_start + queue_idx as usize; + if queue_account_pos < accounts.len() { + queue_pubkey = Some(accounts[queue_account_pos].pubkey); + } + } + } + + (tree_pubkey, queue_pubkey) +} + +/// Decode instruction data for known programs +pub fn decode_instruction( + program_id: &Pubkey, + data: &[u8], + accounts: &[AccountMeta], +) -> Option { + match program_id.to_string().as_str() { + // Light System Program + "SySTEM1eSU2p4BGQfQpimFEWWSC1XDFeun3Nqzz3rT7" => { + decode_light_system_instruction(data, accounts, program_id) + } + + // Compute Budget Program + "ComputeBudget111111111111111111111111111111" => decode_compute_budget_instruction(data), + + // System Program + id if id == system_program::ID.to_string() => decode_system_instruction(data), + + // Account Compression Program + "compr6CUsB5m2jS4Y3831ztGSTnDpnKJTKS95d64XVq" => decode_compression_instruction(data), + + // Compressed Token Program + "cTokenmWW8bLPjZEBAUgYy3zKxQZW6VKi7bqNFEVv3m" => decode_compressed_token_instruction(data), + + _ => Some(ParsedInstructionData::Unknown { + program_name: get_program_name(program_id), + data_preview: bs58::encode(&data[..data.len().min(16)]).into_string(), + }), + } +} + +/// Decode Light System Program instructions +fn decode_light_system_instruction( + data: &[u8], + accounts: &[AccountMeta], + program_id: &Pubkey, +) -> Option { + if data.is_empty() { + return None; + } + + // Light System Program uses 8-byte discriminators + if data.len() < 8 { + return Some(ParsedInstructionData::LightSystemProgram { + instruction_type: "Invalid".to_string(), + compressed_accounts: None, + proof_info: None, + address_params: None, + fee_info: None, + input_account_data: None, + output_account_data: None, + }); + } + + // Extract the 8-byte discriminator + let discriminator: [u8; 8] = data[0..8].try_into().unwrap(); + + // Light Protocol discriminators from compressed-account/src/discriminators.rs + let ( + instruction_type, + compressed_accounts, + proof_info, + address_params, + fee_info, + input_account_data, + output_account_data, + ) = match discriminator { + [26, 16, 169, 7, 21, 202, 242, 25] => { + // DISCRIMINATOR_INVOKE + match parse_invoke_instruction(&data[8..], accounts) { + Ok(parsed) => parsed, + Err(_) => ( + "Invoke (parse error)".to_string(), + None, + None, + None, + None, + None, + None, + ), + } + } + [49, 212, 191, 129, 39, 194, 43, 196] => { + // DISCRIMINATOR_INVOKE_CPI + match parse_invoke_cpi_instruction(&data[8..], accounts) { + Ok(parsed) => parsed, + Err(_) => ( + "InvokeCpi (parse error)".to_string(), + None, + None, + None, + None, + None, + None, + ), + } + } + [86, 47, 163, 166, 21, 223, 92, 8] => { + // DISCRIMINATOR_INVOKE_CPI_WITH_READ_ONLY + match parse_invoke_cpi_readonly_instruction(&data[8..], accounts) { + Ok(parsed) => parsed, + Err(_) => ( + "InvokeCpiWithReadOnly (parse error)".to_string(), + None, + None, + None, + None, + None, + None, + ), + } + } + [228, 34, 128, 84, 47, 139, 86, 240] => { + // INVOKE_CPI_WITH_ACCOUNT_INFO_INSTRUCTION + match parse_invoke_cpi_account_info_instruction(&data[8..], accounts, program_id) { + Ok(parsed) => parsed, + Err(_) => ( + "InvokeCpiWithAccountInfo (parse error)".to_string(), + None, + None, + None, + None, + None, + None, + ), + } + } + _ => { + // Unknown discriminator - show the discriminator bytes for debugging + let discriminator_str = format!("{:?}", discriminator); + ( + format!("Unknown({})", discriminator_str), + None, + None, + None, + None, + None, + None, + ) + } + }; + + Some(ParsedInstructionData::LightSystemProgram { + instruction_type, + compressed_accounts, + proof_info, + address_params, + fee_info, + input_account_data, + output_account_data, + }) +} + +type InstructionParseResult = Result< + ( + String, + Option, + Option, + Option>, + Option, + Option>, + Option>, + ), + Box, +>; + +/// Parse Invoke instruction data - display data hashes directly +fn parse_invoke_instruction(data: &[u8], accounts: &[AccountMeta]) -> InstructionParseResult { + // Skip the 4-byte vec length prefix that Anchor adds + if data.len() < 4 { + return Err("Instruction data too short for Anchor prefix".into()); + } + let instruction_data = InstructionDataInvoke::try_from_slice(&data[4..])?; + + let compressed_accounts = Some(super::types::CompressedAccountSummary { + input_accounts: instruction_data + .input_compressed_accounts_with_merkle_context + .len(), + output_accounts: instruction_data.output_compressed_accounts.len(), + lamports_change: instruction_data + .compress_or_decompress_lamports + .map(|l| l as i64), + }); + + let proof_info = instruction_data + .proof + .as_ref() + .map(|_| super::types::ProofSummary { + proof_type: "Validity".to_string(), + has_validity_proof: true, + }); + + // Extract actual address parameters with values + let address_params = if !instruction_data.new_address_params.is_empty() { + Some( + instruction_data + .new_address_params + .iter() + .map(|param| super::types::AddressParam { + seed: param.seed, + address_queue_index: Some(param.address_queue_account_index), + merkle_tree_index: Some(param.address_merkle_tree_account_index), + root_index: Some(param.address_merkle_tree_root_index), + derived_address: None, + }) + .collect(), + ) + } else { + None + }; + + // Extract input account data + let input_account_data = if !instruction_data + .input_compressed_accounts_with_merkle_context + .is_empty() + { + Some( + instruction_data + .input_compressed_accounts_with_merkle_context + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_context.merkle_tree_pubkey_index); + let queue_idx = Some(acc.merkle_context.queue_pubkey_index); + let (tree_pubkey, queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, queue_idx); + + super::types::InputAccountData { + lamports: acc.compressed_account.lamports, + owner: Some(acc.compressed_account.owner.into()), + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: queue_idx, + queue_pubkey, + address: acc.compressed_account.address, + data_hash: if let Some(ref data) = acc.compressed_account.data { + data.data_hash.to_vec() + } else { + vec![] + }, + discriminator: if let Some(ref data) = acc.compressed_account.data { + data.discriminator.to_vec() + } else { + vec![] + }, + } + }) + .collect(), + ) + } else { + None + }; + + // Extract output account data + let output_account_data = if !instruction_data.output_compressed_accounts.is_empty() { + Some( + instruction_data + .output_compressed_accounts + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_tree_index); + let (tree_pubkey, _queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, None); + + super::types::OutputAccountData { + lamports: acc.compressed_account.lamports, + data: acc.compressed_account.data.as_ref().map(|d| d.data.clone()), + owner: Some(acc.compressed_account.owner.into()), + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: None, + queue_pubkey: None, + address: acc.compressed_account.address, + data_hash: if let Some(ref data) = acc.compressed_account.data { + data.data_hash.to_vec() + } else { + vec![] + }, + discriminator: if let Some(ref data) = acc.compressed_account.data { + data.discriminator.to_vec() + } else { + vec![] + }, + } + }) + .collect(), + ) + } else { + None + }; + + let fee_info = instruction_data + .relay_fee + .map(|fee| super::types::FeeSummary { + relay_fee: Some(fee), + compression_fee: None, + }); + + Ok(( + "Invoke".to_string(), + compressed_accounts, + proof_info, + address_params, + fee_info, + input_account_data, + output_account_data, + )) +} + +/// Parse InvokeCpi instruction data - display data hashes directly +fn parse_invoke_cpi_instruction(data: &[u8], accounts: &[AccountMeta]) -> InstructionParseResult { + // Skip the 4-byte vec length prefix that Anchor adds + if data.len() < 4 { + return Err("Instruction data too short for Anchor prefix".into()); + } + let instruction_data = InstructionDataInvokeCpi::try_from_slice(&data[4..])?; + + let compressed_accounts = Some(super::types::CompressedAccountSummary { + input_accounts: instruction_data + .input_compressed_accounts_with_merkle_context + .len(), + output_accounts: instruction_data.output_compressed_accounts.len(), + lamports_change: instruction_data + .compress_or_decompress_lamports + .map(|l| l as i64), + }); + + let proof_info = instruction_data + .proof + .as_ref() + .map(|_| super::types::ProofSummary { + proof_type: "Validity".to_string(), + has_validity_proof: true, + }); + + // Extract actual address parameters with values + let address_params = if !instruction_data.new_address_params.is_empty() { + Some( + instruction_data + .new_address_params + .iter() + .map(|param| super::types::AddressParam { + seed: param.seed, + address_queue_index: Some(param.address_queue_account_index), + merkle_tree_index: Some(param.address_merkle_tree_account_index), + root_index: Some(param.address_merkle_tree_root_index), + derived_address: None, + }) + .collect(), + ) + } else { + None + }; + + // Extract input account data + let input_account_data = if !instruction_data + .input_compressed_accounts_with_merkle_context + .is_empty() + { + Some( + instruction_data + .input_compressed_accounts_with_merkle_context + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_context.merkle_tree_pubkey_index); + let queue_idx = Some(acc.merkle_context.queue_pubkey_index); + let (tree_pubkey, queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, queue_idx); + + super::types::InputAccountData { + lamports: acc.compressed_account.lamports, + owner: Some(acc.compressed_account.owner.into()), + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: queue_idx, + queue_pubkey, + address: acc.compressed_account.address, + data_hash: if let Some(ref data) = acc.compressed_account.data { + data.data_hash.to_vec() + } else { + vec![] + }, + discriminator: if let Some(ref data) = acc.compressed_account.data { + data.discriminator.to_vec() + } else { + vec![] + }, + } + }) + .collect(), + ) + } else { + None + }; + + // Extract output account data + let output_account_data = if !instruction_data.output_compressed_accounts.is_empty() { + Some( + instruction_data + .output_compressed_accounts + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_tree_index); + let (tree_pubkey, _queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, None); + + super::types::OutputAccountData { + lamports: acc.compressed_account.lamports, + data: acc.compressed_account.data.as_ref().map(|d| d.data.clone()), + owner: Some(acc.compressed_account.owner.into()), + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: None, + queue_pubkey: None, + address: acc.compressed_account.address, + data_hash: if let Some(ref data) = acc.compressed_account.data { + data.data_hash.to_vec() + } else { + vec![] + }, + discriminator: if let Some(ref data) = acc.compressed_account.data { + data.discriminator.to_vec() + } else { + vec![] + }, + } + }) + .collect(), + ) + } else { + None + }; + + let fee_info = instruction_data + .relay_fee + .map(|fee| super::types::FeeSummary { + relay_fee: Some(fee), + compression_fee: None, + }); + + Ok(( + "InvokeCpi".to_string(), + compressed_accounts, + proof_info, + address_params, + fee_info, + input_account_data, + output_account_data, + )) +} + +/// Parse InvokeCpiWithReadOnly instruction data - display data hashes directly +fn parse_invoke_cpi_readonly_instruction( + data: &[u8], + accounts: &[AccountMeta], +) -> InstructionParseResult { + let instruction_data = InstructionDataInvokeCpiWithReadOnly::try_from_slice(data)?; + + let compressed_accounts = Some(super::types::CompressedAccountSummary { + input_accounts: instruction_data.input_compressed_accounts.len(), + output_accounts: instruction_data.output_compressed_accounts.len(), + lamports_change: if instruction_data.compress_or_decompress_lamports > 0 { + Some(instruction_data.compress_or_decompress_lamports as i64) + } else { + None + }, + }); + + let proof_info = Some(super::types::ProofSummary { + proof_type: "Validity".to_string(), + has_validity_proof: true, + }); + + // Extract actual address parameters with values + let mut address_params = Vec::new(); + + // Add new address parameters with actual values + for param in &instruction_data.new_address_params { + address_params.push(super::types::AddressParam { + seed: param.seed, + address_queue_index: Some(param.address_queue_account_index), + merkle_tree_index: Some(param.address_merkle_tree_account_index), + root_index: Some(param.address_merkle_tree_root_index), + derived_address: None, + }); + } + + // Add readonly address parameters + for readonly_addr in &instruction_data.read_only_addresses { + address_params.push(super::types::AddressParam { + seed: [0; 32], // ReadOnly addresses don't have seeds in the same way + address_queue_index: None, + merkle_tree_index: Some(readonly_addr.address_merkle_tree_account_index), + root_index: Some(readonly_addr.address_merkle_tree_root_index), + derived_address: Some(readonly_addr.address), + }); + } + + let address_params = if !address_params.is_empty() { + Some(address_params) + } else { + None + }; + + // Extract input account data - use data_hash from InAccount + let input_account_data = if !instruction_data.input_compressed_accounts.is_empty() { + Some( + instruction_data + .input_compressed_accounts + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_context.merkle_tree_pubkey_index); + let queue_idx = Some(acc.merkle_context.queue_pubkey_index); + let (tree_pubkey, queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, queue_idx); + + super::types::InputAccountData { + lamports: acc.lamports, + owner: Some(instruction_data.invoking_program_id.into()), // Use invoking program as owner + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: queue_idx, + queue_pubkey, + address: acc.address, + data_hash: acc.data_hash.to_vec(), + discriminator: acc.discriminator.to_vec(), + } + }) + .collect(), + ) + } else { + None + }; + + // Extract output account data + let output_account_data = if !instruction_data.output_compressed_accounts.is_empty() { + Some( + instruction_data + .output_compressed_accounts + .iter() + .map(|acc| { + let tree_idx = Some(acc.merkle_tree_index); + let (tree_pubkey, _queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, None); + + super::types::OutputAccountData { + lamports: acc.compressed_account.lamports, + data: acc.compressed_account.data.as_ref().map(|d| d.data.clone()), + owner: Some(instruction_data.invoking_program_id.into()), // Use invoking program as owner for consistency + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: None, + queue_pubkey: None, + address: acc.compressed_account.address, + data_hash: if let Some(ref data) = acc.compressed_account.data { + data.data_hash.to_vec() + } else { + vec![] + }, + discriminator: if let Some(ref data) = acc.compressed_account.data { + data.discriminator.to_vec() + } else { + vec![] + }, + } + }) + .collect(), + ) + } else { + None + }; + + Ok(( + "InvokeCpiWithReadOnly".to_string(), + compressed_accounts, + proof_info, + address_params, + None, + input_account_data, + output_account_data, + )) +} + +/// Parse InvokeCpiWithAccountInfo instruction data - display data hashes directly +fn parse_invoke_cpi_account_info_instruction( + data: &[u8], + accounts: &[AccountMeta], + program_id: &Pubkey, +) -> InstructionParseResult { + let instruction_data = InstructionDataInvokeCpiWithAccountInfo::try_from_slice(data)?; + + let input_accounts = instruction_data + .account_infos + .iter() + .filter(|a| a.input.is_some()) + .count(); + let output_accounts = instruction_data + .account_infos + .iter() + .filter(|a| a.output.is_some()) + .count(); + + let compressed_accounts = Some(super::types::CompressedAccountSummary { + input_accounts, + output_accounts, + lamports_change: if instruction_data.compress_or_decompress_lamports > 0 { + Some(instruction_data.compress_or_decompress_lamports as i64) + } else { + None + }, + }); + + let proof_info = Some(super::types::ProofSummary { + proof_type: "Validity".to_string(), + has_validity_proof: true, + }); + + // Extract actual address parameters with values + let mut address_params = Vec::new(); + + // Add new address parameters with actual values + for param in &instruction_data.new_address_params { + address_params.push(super::types::AddressParam { + seed: param.seed, + address_queue_index: Some(param.address_queue_account_index), + merkle_tree_index: Some(param.address_merkle_tree_account_index), + root_index: Some(param.address_merkle_tree_root_index), + derived_address: None, + }); + } + + // Add readonly address parameters + for readonly_addr in &instruction_data.read_only_addresses { + address_params.push(super::types::AddressParam { + seed: [0; 32], // ReadOnly addresses don't have seeds in the same way + address_queue_index: None, + merkle_tree_index: Some(readonly_addr.address_merkle_tree_account_index), + root_index: Some(readonly_addr.address_merkle_tree_root_index), + derived_address: Some(readonly_addr.address), + }); + } + + let address_params = if !address_params.is_empty() { + Some(address_params) + } else { + None + }; + + // Extract input account data from account_infos + let input_account_data = { + let mut input_data = Vec::new(); + for account_info in &instruction_data.account_infos { + if let Some(ref input) = account_info.input { + input_data.push(super::types::InputAccountData { + lamports: input.lamports, + owner: Some(*program_id), // Use invoking program as owner + merkle_tree_index: None, // Note: merkle tree context not available in CompressedAccountInfo + merkle_tree_pubkey: None, + queue_index: None, + queue_pubkey: None, + address: account_info.address, // Use address from CompressedAccountInfo + data_hash: input.data_hash.to_vec(), + discriminator: input.discriminator.to_vec(), + }); + } + } + if !input_data.is_empty() { + Some(input_data) + } else { + None + } + }; + + // Extract output account data from account_infos + let output_account_data = { + let mut output_data = Vec::new(); + for account_info in &instruction_data.account_infos { + if let Some(ref output) = account_info.output { + let tree_idx = Some(output.output_merkle_tree_index); + let (tree_pubkey, _queue_pubkey) = + resolve_tree_and_queue_pubkeys(accounts, tree_idx, None); + + output_data.push(super::types::OutputAccountData { + lamports: output.lamports, + data: if !output.data.is_empty() { + Some(output.data.clone()) + } else { + None + }, + owner: Some(*program_id), // Use invoking program as owner + merkle_tree_index: tree_idx, + merkle_tree_pubkey: tree_pubkey, + queue_index: None, + queue_pubkey: None, + address: account_info.address, // Use address from CompressedAccountInfo + data_hash: output.data_hash.to_vec(), + discriminator: output.discriminator.to_vec(), + }); + } + } + if !output_data.is_empty() { + Some(output_data) + } else { + None + } + }; + + Ok(( + "InvokeCpiWithAccountInfo".to_string(), + compressed_accounts, + proof_info, + address_params, + None, + input_account_data, + output_account_data, + )) +} + +/// Decode Compute Budget Program instructions +fn decode_compute_budget_instruction(data: &[u8]) -> Option { + if data.len() < 4 { + return None; + } + + let instruction_discriminator = u32::from_le_bytes([data[0], data[1], data[2], data[3]]); + + match instruction_discriminator { + 0 => { + // RequestUnitsDeprecated + if data.len() >= 12 { + let units = u32::from_le_bytes([data[4], data[5], data[6], data[7]]) as u64; + let _additional_fee = + u32::from_le_bytes([data[8], data[9], data[10], data[11]]) as u64; + Some(ParsedInstructionData::ComputeBudget { + instruction_type: "RequestUnitsDeprecated".to_string(), + value: Some(units), + }) + } else { + None + } + } + 1 => { + // RequestHeapFrame + if data.len() >= 8 { + let bytes = u32::from_le_bytes([data[4], data[5], data[6], data[7]]) as u64; + Some(ParsedInstructionData::ComputeBudget { + instruction_type: "RequestHeapFrame".to_string(), + value: Some(bytes), + }) + } else { + None + } + } + 2 => { + // SetComputeUnitLimit + if data.len() >= 8 { + let units = u32::from_le_bytes([data[4], data[5], data[6], data[7]]) as u64; + Some(ParsedInstructionData::ComputeBudget { + instruction_type: "SetComputeUnitLimit".to_string(), + value: Some(units), + }) + } else { + None + } + } + 3 => { + // SetComputeUnitPrice + if data.len() >= 12 { + let price = u64::from_le_bytes([ + data[4], data[5], data[6], data[7], data[8], data[9], data[10], data[11], + ]); + Some(ParsedInstructionData::ComputeBudget { + instruction_type: "SetComputeUnitPrice".to_string(), + value: Some(price), + }) + } else { + None + } + } + _ => Some(ParsedInstructionData::ComputeBudget { + instruction_type: "Unknown".to_string(), + value: None, + }), + } +} + +/// Decode System Program instructions +fn decode_system_instruction(data: &[u8]) -> Option { + if data.len() < 4 { + return None; + } + + let instruction_type = u32::from_le_bytes([data[0], data[1], data[2], data[3]]); + + match instruction_type { + 0 => { + // CreateAccount + if data.len() >= 52 { + let lamports = u64::from_le_bytes([ + data[4], data[5], data[6], data[7], data[8], data[9], data[10], data[11], + ]); + let space = u64::from_le_bytes([ + data[12], data[13], data[14], data[15], data[16], data[17], data[18], data[19], + ]); + + Some(ParsedInstructionData::System { + instruction_type: "CreateAccount".to_string(), + lamports: Some(lamports), + space: Some(space), + new_account: None, + }) + } else { + None + } + } + 2 => { + // Transfer + if data.len() >= 12 { + let lamports = u64::from_le_bytes([ + data[4], data[5], data[6], data[7], data[8], data[9], data[10], data[11], + ]); + + Some(ParsedInstructionData::System { + instruction_type: "Transfer".to_string(), + lamports: Some(lamports), + space: None, + new_account: None, + }) + } else { + None + } + } + 8 => { + // Allocate + if data.len() >= 12 { + let space = u64::from_le_bytes([ + data[4], data[5], data[6], data[7], data[8], data[9], data[10], data[11], + ]); + + Some(ParsedInstructionData::System { + instruction_type: "Allocate".to_string(), + lamports: None, + space: Some(space), + new_account: None, + }) + } else { + None + } + } + _ => Some(ParsedInstructionData::System { + instruction_type: "Unknown".to_string(), + lamports: None, + space: None, + new_account: None, + }), + } +} + +/// Decode Account Compression Program instructions +fn decode_compression_instruction(data: &[u8]) -> Option { + // Return basic instruction info for account compression + let instruction_name = if data.len() >= 8 { + // Common account compression operations + "InsertIntoQueues" + } else { + "Unknown" + }; + + Some(ParsedInstructionData::Unknown { + program_name: "Account Compression".to_string(), + data_preview: format!("{}({}bytes)", instruction_name, data.len()), + }) +} + +/// Decode Compressed Token Program instructions +fn decode_compressed_token_instruction(data: &[u8]) -> Option { + // Return basic instruction info for compressed token operations + let instruction_name = if data.len() >= 8 { + // Common compressed token operations + "TokenOperation" + } else { + "Unknown" + }; + + Some(ParsedInstructionData::Unknown { + program_name: "Compressed Token".to_string(), + data_preview: format!("{}({}bytes)", instruction_name, data.len()), + }) +} + +/// Get human-readable program name +fn get_program_name(program_id: &Pubkey) -> String { + match program_id.to_string().as_str() { + id if id == system_program::ID.to_string() => "System Program".to_string(), + "ComputeBudget111111111111111111111111111111" => "Compute Budget".to_string(), + "SySTEM1eSU2p4BGQfQpimFEWWSC1XDFeun3Nqzz3rT7" => "Light System Program".to_string(), + "compr6CUsB5m2jS4Y3831ztGSTnDpnKJTKS95d64XVq" => "Account Compression".to_string(), + "FNt7byTHev1k5x2cXZLBr8TdWiC3zoP5vcnZR4P682Uy" => "Test Program".to_string(), + _ => { + let pubkey_str = program_id.to_string(); + format!("Program {}", &pubkey_str[..8]) + } + } +} + +/// Extract Light Protocol events from transaction logs and metadata +pub fn extract_light_events( + logs: &[String], + _events: &Option>, // Light Protocol events for future enhancement +) -> Vec { + let mut light_events = Vec::new(); + + // Parse events from logs + for log in logs { + if log.contains("PublicTransactionEvent") || log.contains("BatchPublicTransactionEvent") { + // Parse Light Protocol events from logs + light_events.push(super::types::LightProtocolEvent { + event_type: "PublicTransactionEvent".to_string(), + compressed_accounts: Vec::new(), + merkle_tree_changes: Vec::new(), + nullifiers: Vec::new(), + }); + } + } + + light_events +} diff --git a/sdk-libs/program-test/src/logging/decoder.rs:70:15 b/sdk-libs/program-test/src/logging/decoder.rs:70:15 new file mode 100644 index 0000000000..e69de29bb2 diff --git a/sdk-libs/program-test/src/logging/decoder.rs:946:15 b/sdk-libs/program-test/src/logging/decoder.rs:946:15 new file mode 100644 index 0000000000..e69de29bb2 diff --git a/sdk-libs/program-test/src/logging/formatter.rs b/sdk-libs/program-test/src/logging/formatter.rs new file mode 100644 index 0000000000..966c2aae35 --- /dev/null +++ b/sdk-libs/program-test/src/logging/formatter.rs @@ -0,0 +1,1235 @@ +//! Transaction formatting utilities for explorer-style output + +use std::fmt::{self, Write}; + +use solana_sdk::system_program; +use tabled::{Table, Tabled}; + +use super::{ + config::{EnhancedLoggingConfig, LogVerbosity}, + types::{ + AccountAccess, AccountChange, EnhancedInstructionLog, EnhancedTransactionLog, + TransactionStatus, + }, +}; + +/// Row for account table display +#[derive(Tabled)] +struct AccountRow { + #[tabled(rename = "Access")] + symbol: String, + #[tabled(rename = "Account")] + pubkey: String, + #[tabled(rename = "Type")] + access: String, + #[tabled(rename = "Name")] + name: String, +} + +/// Colors for terminal output +#[derive(Debug, Clone)] +pub struct Colors { + pub bold: String, + pub reset: String, + pub green: String, + pub red: String, + pub yellow: String, + pub blue: String, + pub cyan: String, + pub gray: String, +} + +impl Colors { + pub fn new(use_colors: bool) -> Self { + if use_colors { + Self { + bold: "\x1b[1m".to_string(), + reset: "\x1b[0m".to_string(), + green: "\x1b[32m".to_string(), + red: "\x1b[31m".to_string(), + yellow: "\x1b[33m".to_string(), + blue: "\x1b[34m".to_string(), + cyan: "\x1b[36m".to_string(), + gray: "\x1b[90m".to_string(), + } + } else { + Self { + bold: String::new(), + reset: String::new(), + green: String::new(), + red: String::new(), + yellow: String::new(), + blue: String::new(), + cyan: String::new(), + gray: String::new(), + } + } + } +} + +/// Transaction formatter with configurable output +pub struct TransactionFormatter { + config: EnhancedLoggingConfig, + colors: Colors, +} + +impl TransactionFormatter { + pub fn new(config: &EnhancedLoggingConfig) -> Self { + Self { + config: config.clone(), + colors: Colors::new(config.use_colors), + } + } + + /// Apply line breaks to long values in the complete output + fn apply_line_breaks(&self, text: &str) -> String { + let mut result = String::new(); + + for line in text.lines() { + // Look for patterns that need line breaking + if let Some(formatted_line) = self.format_line_if_needed(line) { + result.push_str(&formatted_line); + } else { + result.push_str(line); + } + result.push('\n'); + } + + result + } + + /// Format a line if it contains long values that need breaking + fn format_line_if_needed(&self, line: &str) -> Option { + // Extract leading whitespace/indentation and table characters + let leading_chars = line + .chars() + .take_while(|&c| c.is_whitespace() || "│├└┌┬┴┐┤─".contains(c)) + .collect::(); + + // Match patterns like "address: [0, 1, 2, 3, ...]" or "Raw instruction data (N bytes): [...]" + if line.contains(": [") && line.contains("]") { + // Handle byte arrays + if let Some(start) = line.find(": [") { + if let Some(end_pos) = line[start..].find(']') { + let end = start + end_pos; + let prefix = &line[..start + 2]; // Include ": " + let array_part = &line[start + 2..end + 1]; // The "[...]" part + let suffix = &line[end + 1..]; + + // For raw instruction data, use a shorter line length to better fit in terminal + let max_width = if line.contains("Raw instruction data") { + 80 // Wider for raw instruction data to fit more numbers per line + } else { + 50 // Keep existing width for other arrays + }; + + // Always format if it's raw instruction data or if it exceeds max_width + if line.contains("Raw instruction data") || array_part.len() > max_width { + let formatted_array = self.format_long_value_with_indent( + array_part, + max_width, + &leading_chars, + ); + return Some(format!("{}{}{}", prefix, formatted_array, suffix)); + } + } + } + } + + // Handle long base58 strings (44+ characters) in table cells + if line.contains('|') && !line.trim_start().starts_with('|') { + // This is a table content line, not a border + let mut new_line = String::new(); + let mut modified = false; + + // Split by table separators while preserving them + let parts: Vec<&str> = line.split('|').collect(); + for (i, part) in parts.iter().enumerate() { + if i > 0 { + new_line.push('|'); + } + + // Check if this cell contains a long value + for word in part.split_whitespace() { + if word.len() > 44 && word.chars().all(|c| c.is_alphanumeric()) { + let indent = " ".repeat(leading_chars.len() + 2); // Extra space for table formatting + let formatted_word = self.format_long_value_with_indent(word, 44, &indent); + new_line.push_str(&part.replace(word, &formatted_word)); + modified = true; + break; + } + } + + if !modified { + new_line.push_str(part); + } + } + + if modified { + return Some(new_line); + } + } + + None + } + + /// Format long value with proper indentation for continuation lines + fn format_long_value_with_indent(&self, value: &str, max_width: usize, indent: &str) -> String { + if value.len() <= max_width { + return value.to_string(); + } + + let mut result = String::new(); + + // Handle byte arrays specially by breaking at natural comma boundaries when possible + if value.starts_with('[') && value.ends_with(']') { + // This is a byte array - try to break at comma boundaries for better readability + let inner = &value[1..value.len() - 1]; // Remove [ and ] + let parts: Vec<&str> = inner.split(", ").collect(); + + result.push('['); + let mut current_line = String::new(); + let mut first_line = true; + + for (i, part) in parts.iter().enumerate() { + let addition = if i == 0 { + part.to_string() + } else { + format!(", {}", part) + }; + + // Check if adding this part would exceed the line width + if current_line.len() + addition.len() > max_width && !current_line.is_empty() { + // Add current line to result and start new line + if first_line { + result.push_str(¤t_line); + first_line = false; + } else { + result.push_str(&format!("\n{}{}", indent, current_line)); + } + current_line = part.to_string(); + } else { + current_line.push_str(&addition); + } + } + + // Add the last line + if !current_line.is_empty() { + if first_line { + result.push_str(¤t_line); + } else { + result.push_str(&format!("\n{}{}", indent, current_line)); + } + } + + result.push(']'); + } else { + // Fall back to character-based breaking for non-array values + let chars = value.chars().collect::>(); + let mut pos = 0; + + while pos < chars.len() { + let end = (pos + max_width).min(chars.len()); + let chunk: String = chars[pos..end].iter().collect(); + + if pos == 0 { + result.push_str(&chunk); + } else { + result.push_str(&format!("\n{}{}", indent, chunk)); + } + + pos = end; + } + } + + result + } + + /// Format complete transaction log + pub fn format(&self, log: &EnhancedTransactionLog, tx_number: usize) -> String { + let mut output = String::new(); + + // Transaction box header with number + writeln!(output, "{}┌───────────────────────────────────────── Transaction #{} ─────────────────────────────────────────────┐{}", self.colors.gray, tx_number, self.colors.reset).expect("Failed to write box header"); + + // Transaction header + self.write_transaction_header(&mut output, log) + .expect("Failed to write header"); + + // Instructions section + if !log.instructions.is_empty() { + self.write_instructions_section(&mut output, log) + .expect("Failed to write instructions"); + } + + // Account changes section + if self.config.show_account_changes && !log.account_changes.is_empty() { + self.write_account_changes_section(&mut output, log) + .expect("Failed to write account changes"); + } + + // Light Protocol events section + if !log.light_events.is_empty() { + self.write_light_events_section(&mut output, log) + .expect("Failed to write Light Protocol events"); + } + + // Program logs section (LiteSVM pretty logs) + if !log.program_logs_pretty.trim().is_empty() { + self.write_program_logs_section(&mut output, log) + .expect("Failed to write program logs"); + } + + // Transaction box footer + writeln!(output, "{}└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘{}", self.colors.gray, self.colors.reset).expect("Failed to write box footer"); + + // Apply line breaks for long values in the complete output + self.apply_line_breaks(&output) + } + + /// Write transaction header with status, fee, and compute units + fn write_transaction_header( + &self, + output: &mut String, + log: &EnhancedTransactionLog, + ) -> fmt::Result { + writeln!( + output, + "{}│{} {}Transaction: {}{} | Slot: {} | Status: {} {}{}", + self.colors.gray, + self.colors.reset, + self.colors.bold, + self.colors.cyan, + log.signature, + log.slot, + log.status.symbol(), + self.status_color(&log.status), + log.status.text(), + )?; + + writeln!( + output, + "{}│{} Fee: {}{:.6} SOL | Compute Used: {}{}/{} CU{}", + self.colors.gray, + self.colors.reset, + self.colors.yellow, + log.fee as f64 / 1_000_000_000.0, + self.colors.blue, + log.compute_used, + log.compute_total, + self.colors.reset + )?; + + writeln!(output, "{}│{}", self.colors.gray, self.colors.reset)?; + Ok(()) + } + + /// Write instructions hierarchy + fn write_instructions_section( + &self, + output: &mut String, + log: &EnhancedTransactionLog, + ) -> fmt::Result { + writeln!( + output, + "{}│{} {}Instructions ({}):{}", + self.colors.gray, + self.colors.reset, + self.colors.bold, + log.instructions.len(), + self.colors.reset + )?; + writeln!(output, "{}│{}", self.colors.gray, self.colors.reset)?; + + for (i, instruction) in log.instructions.iter().enumerate() { + self.write_instruction(output, instruction, 0, i + 1)?; + } + + Ok(()) + } + + /// Write single instruction with proper indentation and hierarchy + fn write_instruction( + &self, + output: &mut String, + instruction: &EnhancedInstructionLog, + depth: usize, + number: usize, + ) -> fmt::Result { + let indent = self.get_tree_indent(depth); + let prefix = if depth == 0 { "├─" } else { "└─" }; + + // Instruction header + let inner_count = if instruction.inner_instructions.is_empty() { + String::new() + } else { + format!(".{}", instruction.inner_instructions.len()) + }; + + write!( + output, + "{}{} {}#{}{} {}{} ({}{}{})", + indent, + prefix, + self.colors.bold, + number, + inner_count, + self.colors.blue, + instruction.program_id, + self.colors.cyan, + instruction.program_name, + self.colors.reset + )?; + + // Add instruction name if parsed + if let Some(ref name) = instruction.instruction_name { + write!( + output, + " - {}{}{}", + self.colors.yellow, name, self.colors.reset + )?; + } + + // Add compute units if available and requested + if self.config.show_compute_units { + if let Some(compute) = instruction.compute_consumed { + write!( + output, + " {}({}{}CU{})", + self.colors.gray, self.colors.blue, compute, self.colors.gray + )?; + } + } + + writeln!(output, "{}", self.colors.reset)?; + + // Show instruction details based on verbosity + match self.config.verbosity { + LogVerbosity::Detailed | LogVerbosity::Full => { + if let Some(ref parsed) = instruction.parsed_data { + self.write_parsed_instruction_data( + output, + parsed, + &instruction.data, + depth + 1, + )?; + } else if !instruction.data.is_empty() { + // Show raw instruction data for unparseable instructions with chunking + // Skip instruction data for account compression program unless explicitly configured + let should_show_data = if instruction.program_name == "Account Compression" { + self.config.show_compression_instruction_data + } else { + true + }; + + if should_show_data { + let indent = self.get_tree_indent(depth + 1); + writeln!( + output, + "{}{}Raw instruction data ({} bytes): {}[", + indent, + self.colors.gray, + instruction.data.len(), + self.colors.cyan + )?; + + // Chunk the data into 32-byte groups for better readability + for (i, chunk) in instruction.data.chunks(32).enumerate() { + write!(output, "{} ", indent)?; + for (j, byte) in chunk.iter().enumerate() { + if j > 0 { + write!(output, ", ")?; + } + write!(output, "{}", byte)?; + } + if i < instruction.data.chunks(32).len() - 1 { + writeln!(output, ",")?; + } else { + writeln!(output, "]{}", self.colors.reset)?; + } + } + } + } + } + _ => {} + } + + // Show accounts if verbose + if self.config.verbosity == LogVerbosity::Full && !instruction.accounts.is_empty() { + let accounts_indent = self.get_tree_indent(depth + 1); + writeln!( + output, + "{}{}Accounts ({}):{}", + accounts_indent, + self.colors.gray, + instruction.accounts.len(), + self.colors.reset + )?; + + // Create a table for better account formatting + let mut account_rows: Vec = Vec::new(); + + for account in instruction.accounts.iter() { + let access = if account.is_signer && account.is_writable { + AccountAccess::SignerWritable + } else if account.is_signer { + AccountAccess::Signer + } else if account.is_writable { + AccountAccess::Writable + } else { + AccountAccess::Readonly + }; + + let account_name = self.get_account_name(&account.pubkey); + account_rows.push(AccountRow { + symbol: access.symbol().to_string(), + pubkey: account.pubkey.to_string(), + access: access.text().to_string(), + name: account_name, + }); + } + + if !account_rows.is_empty() { + let table = Table::new(account_rows) + .to_string() + .lines() + .map(|line| format!("{}{}", accounts_indent, line)) + .collect::>() + .join("\n"); + writeln!(output, "{}", table)?; + } + } + + // Write inner instructions recursively + for (i, inner) in instruction.inner_instructions.iter().enumerate() { + if depth < self.config.max_inner_instruction_depth { + self.write_instruction(output, inner, depth + 1, i + 1)?; + } + } + + Ok(()) + } + + /// Write parsed instruction data + fn write_parsed_instruction_data( + &self, + output: &mut String, + parsed: &super::types::ParsedInstructionData, + instruction_data: &[u8], + depth: usize, + ) -> fmt::Result { + let indent = self.get_tree_indent(depth); + + match parsed { + super::types::ParsedInstructionData::LightSystemProgram { + instruction_type, + compressed_accounts, + proof_info, + address_params, + fee_info, + input_account_data, + output_account_data, + } => { + writeln!( + output, + "{}{}Light System: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + instruction_type, + self.colors.reset + )?; + + if let Some(compressed_accounts) = compressed_accounts { + writeln!( + output, + "{}{}Accounts: {}in: {}, out: {}{}", + indent, + self.colors.gray, + self.colors.cyan, + compressed_accounts.input_accounts, + compressed_accounts.output_accounts, + self.colors.reset + )?; + } + + if let Some(proof_info) = proof_info { + if proof_info.has_validity_proof { + writeln!( + output, + "{}{}Proof: {}{} proof{}", + indent, + self.colors.gray, + self.colors.cyan, + proof_info.proof_type, + self.colors.reset + )?; + } + } + + // Display input account data + if let Some(ref input_accounts) = input_account_data { + writeln!( + output, + "{}{}Input Accounts ({}):{}", + indent, + self.colors.gray, + input_accounts.len(), + self.colors.reset + )?; + for (i, acc_data) in input_accounts.iter().enumerate() { + writeln!( + output, + "{} {}[{}]{}", + indent, self.colors.gray, i, self.colors.reset + )?; + writeln!( + output, + "{} {}owner: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + acc_data + .owner + .map(|o| o.to_string()) + .unwrap_or("None".to_string()), + self.colors.reset + )?; + if let Some(ref address) = acc_data.address { + writeln!( + output, + "{} {}address: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + address, + self.colors.reset + )?; + } + writeln!( + output, + "{} {}lamports: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.lamports, + self.colors.reset + )?; + if !acc_data.data_hash.is_empty() { + writeln!( + output, + "{} {}data_hash: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.data_hash, + self.colors.reset + )?; + } + if !acc_data.discriminator.is_empty() { + writeln!( + output, + "{} {}discriminator: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.discriminator, + self.colors.reset + )?; + } + if let Some(tree_idx) = acc_data.merkle_tree_index { + if let Some(tree_pubkey) = acc_data.merkle_tree_pubkey { + writeln!( + output, + "{} {}merkle_tree_pubkey (index {}{}{}): {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + tree_idx, + self.colors.gray, + self.colors.yellow, + tree_pubkey, + self.colors.reset + )?; + } else { + writeln!( + output, + "{} {}merkle_tree_index: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + tree_idx, + self.colors.reset + )?; + } + } else if let Some(tree_pubkey) = acc_data.merkle_tree_pubkey { + writeln!( + output, + "{} {}merkle_tree_pubkey: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + tree_pubkey, + self.colors.reset + )?; + } + if let Some(queue_idx) = acc_data.queue_index { + if let Some(queue_pubkey) = acc_data.queue_pubkey { + writeln!( + output, + "{} {}queue_pubkey (index {}{}{}): {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + queue_idx, + self.colors.gray, + self.colors.yellow, + queue_pubkey, + self.colors.reset + )?; + } else { + writeln!( + output, + "{} {}queue_index: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + queue_idx, + self.colors.reset + )?; + } + } else if let Some(queue_pubkey) = acc_data.queue_pubkey { + writeln!( + output, + "{} {}queue_pubkey: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + queue_pubkey, + self.colors.reset + )?; + } + } + } + + // Display output account data + if let Some(ref output_data) = output_account_data { + writeln!( + output, + "{}{}Output Accounts ({}):{}", + indent, + self.colors.gray, + output_data.len(), + self.colors.reset + )?; + for (i, acc_data) in output_data.iter().enumerate() { + writeln!( + output, + "{} {}[{}]{}", + indent, self.colors.gray, i, self.colors.reset + )?; + writeln!( + output, + "{} {}owner: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + acc_data + .owner + .map(|o| o.to_string()) + .unwrap_or("None".to_string()), + self.colors.reset + )?; + if let Some(ref address) = acc_data.address { + writeln!( + output, + "{} {}address: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + address, + self.colors.reset + )?; + } + writeln!( + output, + "{} {}lamports: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.lamports, + self.colors.reset + )?; + if !acc_data.data_hash.is_empty() { + writeln!( + output, + "{} {}data_hash: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.data_hash, + self.colors.reset + )?; + } + if !acc_data.discriminator.is_empty() { + writeln!( + output, + "{} {}discriminator: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + acc_data.discriminator, + self.colors.reset + )?; + } + if let Some(ref data) = acc_data.data { + writeln!( + output, + "{} {}data ({} bytes): {}{:?}{}", + indent, + self.colors.gray, + data.len(), + self.colors.cyan, + data, + self.colors.reset + )?; + } + if let Some(tree_idx) = acc_data.merkle_tree_index { + if let Some(tree_pubkey) = acc_data.merkle_tree_pubkey { + writeln!( + output, + "{} {}merkle_tree_pubkey (index {}{}{}): {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + tree_idx, + self.colors.gray, + self.colors.yellow, + tree_pubkey, + self.colors.reset + )?; + } else { + writeln!( + output, + "{} {}merkle_tree_index: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + tree_idx, + self.colors.reset + )?; + } + } else if let Some(tree_pubkey) = acc_data.merkle_tree_pubkey { + writeln!( + output, + "{} {}merkle_tree_pubkey: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + tree_pubkey, + self.colors.reset + )?; + } + } + } + + // Display address parameters with actual values + if let Some(address_params) = address_params { + writeln!( + output, + "{}{}New Addresses ({}):{}", + indent, + self.colors.gray, + address_params.len(), + self.colors.reset + )?; + for (i, addr_param) in address_params.iter().enumerate() { + writeln!( + output, + "{} {}[{}] {}seed: {}{:?}{}", + indent, + self.colors.gray, + i, + self.colors.gray, + self.colors.cyan, + addr_param.seed, + self.colors.reset + )?; + if let Some(queue_idx) = addr_param.address_queue_index { + writeln!( + output, + "{} {}queue_idx: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + queue_idx, + self.colors.reset + )?; + } + if let Some(tree_idx) = addr_param.merkle_tree_index { + writeln!( + output, + "{} {}tree_idx: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + tree_idx, + self.colors.reset + )?; + } + if let Some(root_idx) = addr_param.root_index { + writeln!( + output, + "{} {}root_idx: {}{}{}", + indent, + self.colors.gray, + self.colors.cyan, + root_idx, + self.colors.reset + )?; + } + if let Some(ref derived_addr) = addr_param.derived_address { + writeln!( + output, + "{} {}address: {}{:?}{}", + indent, + self.colors.gray, + self.colors.cyan, + derived_addr, + self.colors.reset + )?; + } + } + } + + if let Some(fee_info) = fee_info { + if let Some(relay_fee) = fee_info.relay_fee { + writeln!( + output, + "{}{}Relay Fee: {}{} lamports{}", + indent, + self.colors.gray, + self.colors.yellow, + relay_fee, + self.colors.reset + )?; + } + if let Some(compression_fee) = fee_info.compression_fee { + writeln!( + output, + "{}{}Compression Fee: {}{} lamports{}", + indent, + self.colors.gray, + self.colors.yellow, + compression_fee, + self.colors.reset + )?; + } + } + } + super::types::ParsedInstructionData::ComputeBudget { + instruction_type, + value, + } => { + write!( + output, + "{}{}Compute Budget: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + instruction_type, + self.colors.reset + )?; + + if let Some(val) = value { + writeln!(output, " ({})", val)?; + } else { + writeln!(output)?; + } + } + super::types::ParsedInstructionData::System { + instruction_type, + lamports, + space: _, + new_account: _, + } => { + write!( + output, + "{}{}System: {}{}{}", + indent, + self.colors.gray, + self.colors.yellow, + instruction_type, + self.colors.reset + )?; + + if let Some(amount) = lamports { + writeln!(output, " ({} lamports)", amount)?; + } else { + writeln!(output)?; + } + } + super::types::ParsedInstructionData::Unknown { + program_name, + data_preview: _, + } => { + writeln!( + output, + "{}{}Program: {}{}{}", + indent, self.colors.gray, self.colors.yellow, program_name, self.colors.reset + )?; + + // Show raw instruction data for unknown programs with chunking + // Skip instruction data for account compression program unless explicitly configured + let should_show_data = if program_name == "Account Compression" { + self.config.show_compression_instruction_data + } else { + true + }; + + if !instruction_data.is_empty() && should_show_data { + writeln!( + output, + "{}{}Raw instruction data ({} bytes): {}[", + indent, + self.colors.gray, + instruction_data.len(), + self.colors.cyan + )?; + + // Chunk the data into 32-byte groups for better readability + for (i, chunk) in instruction_data.chunks(32).enumerate() { + write!(output, "{} ", indent)?; + for (j, byte) in chunk.iter().enumerate() { + if j > 0 { + write!(output, ", ")?; + } + write!(output, "{}", byte)?; + } + if i < instruction_data.chunks(32).len() - 1 { + writeln!(output, ",")?; + } else { + writeln!(output, "]{}", self.colors.reset)?; + } + } + } + } + } + + Ok(()) + } + + /// Write account changes section + fn write_account_changes_section( + &self, + output: &mut String, + log: &EnhancedTransactionLog, + ) -> fmt::Result { + writeln!(output)?; + writeln!( + output, + "{}Account Changes ({}):{}\n", + self.colors.bold, + log.account_changes.len(), + self.colors.reset + )?; + + for change in &log.account_changes { + self.write_account_change(output, change)?; + } + + Ok(()) + } + + /// Write single account change + fn write_account_change(&self, output: &mut String, change: &AccountChange) -> fmt::Result { + writeln!( + output, + "│ {}{} {} ({}) - {}{}{}", + change.access.symbol(), + self.colors.cyan, + change.pubkey, + change.access.text(), + self.colors.yellow, + change.account_type, + self.colors.reset + )?; + + if change.lamports_before != change.lamports_after { + writeln!( + output, + "│ {}Lamports: {} → {}{}", + self.colors.gray, change.lamports_before, change.lamports_after, self.colors.reset + )?; + } + + Ok(()) + } + + /// Write Light Protocol events section + fn write_light_events_section( + &self, + output: &mut String, + log: &EnhancedTransactionLog, + ) -> fmt::Result { + writeln!(output)?; + writeln!( + output, + "{}Light Protocol Events ({}):{}\n", + self.colors.bold, + log.light_events.len(), + self.colors.reset + )?; + + for event in &log.light_events { + writeln!( + output, + "│ {}Event: {}{}{}", + self.colors.blue, self.colors.yellow, event.event_type, self.colors.reset + )?; + + if !event.compressed_accounts.is_empty() { + writeln!( + output, + "│ {}Compressed Accounts: {}{}", + self.colors.gray, + event.compressed_accounts.len(), + self.colors.reset + )?; + } + + if !event.merkle_tree_changes.is_empty() { + writeln!( + output, + "│ {}Merkle Tree Changes: {}{}", + self.colors.gray, + event.merkle_tree_changes.len(), + self.colors.reset + )?; + } + } + + Ok(()) + } + + /// Write program logs section using LiteSVM's pretty logs + fn write_program_logs_section( + &self, + output: &mut String, + log: &EnhancedTransactionLog, + ) -> fmt::Result { + writeln!(output)?; + writeln!( + output, + "{}│{} {}Program Logs:{}", + self.colors.gray, self.colors.reset, self.colors.bold, self.colors.reset + )?; + writeln!(output, "{}│{}", self.colors.gray, self.colors.reset)?; + + // Display LiteSVM's pretty formatted logs with proper indentation + for line in log.program_logs_pretty.lines() { + if !line.trim().is_empty() { + writeln!( + output, + "{}│{} {}", + self.colors.gray, self.colors.reset, line + )?; + } + } + + Ok(()) + } + + /// Get tree-style indentation for given depth + fn get_tree_indent(&self, depth: usize) -> String { + let border = format!("{}│{} ", self.colors.gray, self.colors.reset); + if depth == 0 { + border + } else { + format!("{}{}", border, "│ ".repeat(depth)) + } + } + + /// Get color for transaction status + fn status_color(&self, status: &TransactionStatus) -> &str { + match status { + TransactionStatus::Success => &self.colors.green, + TransactionStatus::Failed(_) => &self.colors.red, + TransactionStatus::Unknown => &self.colors.yellow, + } + } + + /// Get human-readable name for known accounts using constants and test accounts + fn get_account_name(&self, pubkey: &solana_sdk::pubkey::Pubkey) -> String { + let pubkey_bytes = pubkey.to_bytes(); + + // Light Protocol Programs and Accounts from constants + if pubkey_bytes == light_sdk_types::constants::LIGHT_SYSTEM_PROGRAM_ID { + return "light system program".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::ACCOUNT_COMPRESSION_PROGRAM_ID { + return "account compression program".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::REGISTERED_PROGRAM_PDA { + return "registered program pda".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::ACCOUNT_COMPRESSION_AUTHORITY_PDA { + return "account compression authority".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::NOOP_PROGRAM_ID { + return "noop program".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::C_TOKEN_PROGRAM_ID { + return "compressed token program".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::ADDRESS_TREE_V1 { + return "address tree v1".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::ADDRESS_QUEUE_V1 { + return "address queue v1".to_string(); + } + if pubkey_bytes == light_sdk_types::constants::SOL_POOL_PDA { + return "sol pool pda".to_string(); + } + + // String-based matches for test accounts and other addresses + match pubkey.to_string().as_str() { + "FNt7byTHev1k5x2cXZLBr8TdWiC3zoP5vcnZR4P682Uy" => "test program".to_string(), + + // Test accounts from test_accounts.rs - Local Test Validator + "smt1NamzXdq4AMqS2fS2F1i5KTYPZRhoHgWx38d8WsT" => "v1 state merkle tree".to_string(), + "nfq1NvQDJ2GEgnS8zt9prAe8rjjpAW1zFkrvZoBR148" => "v1 nullifier queue".to_string(), + "cpi1uHzrEhBG733DoEJNgHCyRS3XmmyVNZx5fonubE4" => "v1 cpi context".to_string(), + "amt1Ayt45jfbdw5YSo7iz6WZxUmnZsQTYXy82hVwyC2" => "v1 address merkle tree".to_string(), + "aq1S9z4reTSQAdgWHGD2zDaS39sjGrAxbR31vxJ2F4F" => "v1 address queue".to_string(), + + // V2 State Trees and Queues (test accounts) + "6L7SzhYB3anwEQ9cphpJ1U7Scwj57bx2xueReg7R9cKU" => "v2 state output queue".to_string(), + "HLKs5NJ8FXkJg8BrzJt56adFYYuwg5etzDtBbQYTsixu" => "v2 state merkle tree".to_string(), + "7Hp52chxaew8bW1ApR4fck2bh6Y8qA1pu3qwH6N9zaLj" => "v2 cpi context".to_string(), + + // V2 Address Trees (test accounts) + "EzKE84aVTkCUhDHLELqyJaq1Y7UVVmqxXqZjVHwHY3rK" => "v2 address merkle tree".to_string(), + + // CPI Authority (commonly used in tests) + "HZH7qSLcpAeDqCopVU4e5XkhT9j3JFsQiq8CmruY3aru" => "cpi authority pda".to_string(), + + // Solana Native Programs + id if id == system_program::ID.to_string() => "system program".to_string(), + "ComputeBudget111111111111111111111111111111" => "compute budget program".to_string(), + "TokenkegQfeZyiNwAJbNbGKPFXCWuBvf9Ss623VQ5DA" => "token program".to_string(), + "ATokenGPvbdGVxr1b2hvZbsiqW5xWH25efTNsLJA8knL" => { + "associated token program".to_string() + } + + _ => { + // Check if it's a PDA or regular account + if pubkey.is_on_curve() { + "user account".to_string() + } else { + "pda account".to_string() + } + } + } + } +} diff --git a/sdk-libs/program-test/src/logging/formatter.rs:1218:19 b/sdk-libs/program-test/src/logging/formatter.rs:1218:19 new file mode 100644 index 0000000000..e69de29bb2 diff --git a/sdk-libs/program-test/src/logging/mod.rs b/sdk-libs/program-test/src/logging/mod.rs new file mode 100644 index 0000000000..01033d2846 --- /dev/null +++ b/sdk-libs/program-test/src/logging/mod.rs @@ -0,0 +1,195 @@ +//! Enhanced logging system for light-program-test +//! +//! This module provides Solana Explorer-like transaction logging with: +//! - Hierarchical instruction display with inner instructions +//! - Account changes tracking +//! - Light Protocol specific parsing and formatting +//! - Configurable verbosity levels +//! - Color-coded output +//! +//! Logging behavior: +//! - File logging: Always enabled when `enhanced_logging.enabled = true` (default) +//! - Log file: Written to `target/light_program_test.log` +//! - Console output: Only when `RUST_BACKTRACE` is set AND `log_events = true` +//! - Log file is overwritten at session start, then appended for each transaction + +pub mod config; +pub mod decoder; +pub mod formatter; +pub mod types; + +use std::{ + fs::OpenOptions, + io::Write, + path::PathBuf, + time::{SystemTime, UNIX_EPOCH}, +}; + +pub use config::{EnhancedLoggingConfig, LogVerbosity}; +pub use formatter::TransactionFormatter; +use litesvm::types::TransactionResult; +use solana_sdk::{signature::Signature, transaction::Transaction}; +pub use types::{ + AccountChange, EnhancedInstructionLog, EnhancedTransactionLog, ParsedInstructionData, + TransactionStatus, +}; + +use crate::program_test::config::ProgramTestConfig; + +static SESSION_STARTED: std::sync::Once = std::sync::Once::new(); + +/// Get the log file path in target directory +fn get_log_file_path() -> PathBuf { + // Always use cargo workspace target directory + use std::process::Command; + if let Ok(output) = Command::new("cargo") + .arg("metadata") + .arg("--format-version=1") + .arg("--no-deps") + .output() + { + if output.status.success() { + if let Ok(metadata) = String::from_utf8(output.stdout) { + if let Ok(json) = serde_json::from_str::(&metadata) { + if let Some(target_directory) = json["target_directory"].as_str() { + let mut path = PathBuf::from(target_directory); + path.push("light_program_test.log"); + return path; + } + } + } + } + } + + // Fallback to current directory's target + let mut path = PathBuf::from("target"); + path.push("light_program_test.log"); + path +} + +/// Initialize log file with session header (called only once per session) +fn initialize_log_file() { + SESSION_STARTED.call_once(|| { + let log_path = get_log_file_path(); + let timestamp = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default() + .as_secs(); + + // Create new log file with session header + if let Ok(mut file) = OpenOptions::new() + .create(true) + .write(true) + .truncate(true) + .open(&log_path) + { + let _ = writeln!( + file, + "=== Light Program Test Session Started at Unix Timestamp: {} ===\n", + timestamp + ); + } + }); +} + +/// Strip ANSI escape codes from string for plain text log files +fn strip_ansi_codes(text: &str) -> String { + // Simple regex-free approach to remove ANSI escape sequences + let mut result = String::with_capacity(text.len()); + let mut chars = text.chars(); + + while let Some(ch) = chars.next() { + if ch == '\x1b' { + // Found escape character, skip until we find 'm' (end of color code) + for next_ch in chars.by_ref() { + if next_ch == 'm' { + break; + } + } + } else { + result.push(ch); + } + } + + result +} + +/// Write log entry to file (append to existing session log) +fn write_to_log_file(content: &str) { + // Ensure session is initialized + initialize_log_file(); + + let log_path = get_log_file_path(); + + // Ensure parent directory exists + if let Some(parent) = log_path.parent() { + let _ = std::fs::create_dir_all(parent); + } + + // Strip ANSI color codes for file output + let clean_content = strip_ansi_codes(content); + + // Append transaction log to existing file + if let Ok(mut file) = OpenOptions::new().create(true).append(true).open(&log_path) { + let _ = writeln!(file, "{}", clean_content); + } +} + +/// Main entry point for enhanced transaction logging +pub fn log_transaction_enhanced( + config: &ProgramTestConfig, + transaction: &Transaction, + result: &TransactionResult, + signature: &Signature, + slot: u64, + transaction_counter: usize, +) { + log_transaction_enhanced_with_console( + config, + transaction, + result, + signature, + slot, + transaction_counter, + false, + ) +} + +/// Enhanced transaction logging with console output control +pub fn log_transaction_enhanced_with_console( + config: &ProgramTestConfig, + transaction: &Transaction, + result: &TransactionResult, + signature: &Signature, + slot: u64, + transaction_counter: usize, + print_to_console: bool, +) { + if !config.enhanced_logging.enabled { + return; + } + + let enhanced_log = EnhancedTransactionLog::from_transaction_result( + transaction, + result, + signature, + slot, + &config.enhanced_logging, + ); + + let formatter = TransactionFormatter::new(&config.enhanced_logging); + let formatted_log = formatter.format(&enhanced_log, transaction_counter); + + // Always write to log file when enhanced logging is enabled + write_to_log_file(&formatted_log); + + // Print to console if requested + if print_to_console { + println!("{}", formatted_log); + } +} + +/// Check if enhanced logging should be used instead of basic logging +pub fn should_use_enhanced_logging(config: &ProgramTestConfig) -> bool { + config.enhanced_logging.enabled && !config.no_logs +} diff --git a/sdk-libs/program-test/src/logging/types.rs b/sdk-libs/program-test/src/logging/types.rs new file mode 100644 index 0000000000..0f4490cbfb --- /dev/null +++ b/sdk-libs/program-test/src/logging/types.rs @@ -0,0 +1,480 @@ +//! Type definitions for enhanced logging + +use solana_sdk::{ + inner_instruction::InnerInstruction, instruction::AccountMeta, pubkey::Pubkey, + signature::Signature, system_program, +}; + +use super::config::EnhancedLoggingConfig; + +/// Enhanced transaction log containing all formatting information +#[derive(Debug, Clone)] +pub struct EnhancedTransactionLog { + pub signature: Signature, + pub slot: u64, + pub status: TransactionStatus, + pub fee: u64, + pub compute_used: u64, + pub compute_total: u64, + pub instructions: Vec, + pub account_changes: Vec, + pub program_logs_pretty: String, + pub light_events: Vec, +} + +/// Transaction execution status +#[derive(Debug, Clone)] +pub enum TransactionStatus { + Success, + Failed(String), + Unknown, +} + +impl TransactionStatus { + pub fn symbol(&self) -> &'static str { + match self { + TransactionStatus::Success => "✅", + TransactionStatus::Failed(_) => "❌", + TransactionStatus::Unknown => "⚠️", + } + } + + pub fn text(&self) -> String { + match self { + TransactionStatus::Success => "Success".to_string(), + TransactionStatus::Failed(err) => format!("Failed: {}", err), + TransactionStatus::Unknown => "Unknown".to_string(), + } + } +} + +/// Enhanced instruction log with hierarchy and parsing +#[derive(Debug, Clone)] +pub struct EnhancedInstructionLog { + pub index: usize, + pub program_id: Pubkey, + pub program_name: String, + pub instruction_name: Option, + pub accounts: Vec, + pub data: Vec, + pub parsed_data: Option, + pub inner_instructions: Vec, + pub compute_consumed: Option, + pub success: bool, + pub depth: usize, +} + +/// Parsed instruction data for known programs +#[derive(Debug, Clone)] +pub enum ParsedInstructionData { + LightSystemProgram { + instruction_type: String, + compressed_accounts: Option, + proof_info: Option, + address_params: Option>, + fee_info: Option, + input_account_data: Option>, + output_account_data: Option>, + }, + ComputeBudget { + instruction_type: String, + value: Option, + }, + System { + instruction_type: String, + lamports: Option, + space: Option, + new_account: Option, + }, + Unknown { + program_name: String, + data_preview: String, + }, +} + +/// Summary of compressed accounts in a Light Protocol instruction +#[derive(Debug, Clone)] +pub struct CompressedAccountSummary { + pub input_accounts: usize, + pub output_accounts: usize, + pub lamports_change: Option, +} + +/// Summary of proof information +#[derive(Debug, Clone)] +pub struct ProofSummary { + pub proof_type: String, + pub has_validity_proof: bool, +} + +/// Summary of fee information +#[derive(Debug, Clone)] +pub struct FeeSummary { + pub relay_fee: Option, + pub compression_fee: Option, +} + +/// Address parameter information +#[derive(Debug, Clone)] +pub struct AddressParam { + pub seed: [u8; 32], + pub address_queue_index: Option, + pub merkle_tree_index: Option, + pub root_index: Option, + pub derived_address: Option<[u8; 32]>, +} + +/// Input account data +#[derive(Debug, Clone)] +pub struct InputAccountData { + pub lamports: u64, + pub owner: Option, + pub merkle_tree_index: Option, + pub merkle_tree_pubkey: Option, + pub queue_index: Option, + pub queue_pubkey: Option, + pub address: Option<[u8; 32]>, + pub data_hash: Vec, + pub discriminator: Vec, +} + +/// Output account data +#[derive(Debug, Clone)] +pub struct OutputAccountData { + pub lamports: u64, + pub data: Option>, + pub owner: Option, + pub merkle_tree_index: Option, + pub merkle_tree_pubkey: Option, + pub queue_index: Option, + pub queue_pubkey: Option, + pub address: Option<[u8; 32]>, + pub data_hash: Vec, + pub discriminator: Vec, +} + +/// Account state changes during transaction +#[derive(Debug, Clone)] +pub struct AccountChange { + pub pubkey: Pubkey, + pub account_type: String, + pub access: AccountAccess, + pub lamports_before: u64, + pub lamports_after: u64, + pub data_len_before: usize, + pub data_len_after: usize, + pub owner: Pubkey, + pub executable: bool, + pub rent_epoch: u64, +} + +/// Account access pattern during transaction +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum AccountAccess { + Readonly, + Writable, + Signer, + SignerWritable, +} + +impl AccountAccess { + pub fn symbol(&self) -> &'static str { + match self { + AccountAccess::Readonly => "👁️", + AccountAccess::Writable => "✏️", + AccountAccess::Signer => "🔑", + AccountAccess::SignerWritable => "🔐", + } + } + + pub fn text(&self) -> &'static str { + match self { + AccountAccess::Readonly => "readonly", + AccountAccess::Writable => "writable", + AccountAccess::Signer => "signer", + AccountAccess::SignerWritable => "signer+writable", + } + } +} + +/// Light Protocol specific events +#[derive(Debug, Clone)] +pub struct LightProtocolEvent { + pub event_type: String, + pub compressed_accounts: Vec, + pub merkle_tree_changes: Vec, + pub nullifiers: Vec, +} + +/// Compressed account information +#[derive(Debug, Clone)] +pub struct CompressedAccountInfo { + pub hash: String, + pub owner: Pubkey, + pub lamports: u64, + pub data: Option>, + pub address: Option, +} + +/// Merkle tree state change +#[derive(Debug, Clone)] +pub struct MerkleTreeChange { + pub tree_pubkey: Pubkey, + pub tree_type: String, + pub sequence_number: u64, + pub leaf_index: u64, +} + +impl EnhancedTransactionLog { + /// Use LiteSVM's pretty logs instead of parsing raw logs + fn get_pretty_logs_string(result: &litesvm::types::TransactionResult) -> String { + match result { + Ok(meta) => meta.pretty_logs(), + Err(failed) => failed.meta.pretty_logs(), + } + } + + /// Create from LiteSVM transaction result + pub fn from_transaction_result( + transaction: &solana_sdk::transaction::Transaction, + result: &litesvm::types::TransactionResult, + signature: &Signature, + slot: u64, + config: &EnhancedLoggingConfig, + ) -> Self { + let (status, compute_consumed) = match result { + Ok(meta) => (TransactionStatus::Success, meta.compute_units_consumed), + Err(failed) => ( + TransactionStatus::Failed(format!("{:?}", failed.err)), + failed.meta.compute_units_consumed, + ), + }; + + // Calculate estimated fee (basic calculation: signatures * lamports_per_signature) + // Default Solana fee is 5000 lamports per signature + let estimated_fee = (transaction.signatures.len() as u64) * 5000; + + // Parse instructions + let instructions: Vec = transaction + .message + .instructions + .iter() + .enumerate() + .map(|(index, ix)| EnhancedInstructionLog { + index, + program_id: transaction.message.account_keys[ix.program_id_index as usize], + program_name: get_program_name( + &transaction.message.account_keys[ix.program_id_index as usize], + ), + instruction_name: None, // Will be filled by decoder + accounts: ix + .accounts + .iter() + .map(|&idx| AccountMeta { + pubkey: transaction.message.account_keys[idx as usize], + is_signer: transaction.message.is_signer(idx as usize), + is_writable: transaction.message.is_maybe_writable(idx as usize, None), + }) + .collect(), + data: ix.data.clone(), + parsed_data: None, // Will be filled by decoder + inner_instructions: Vec::new(), // Will be filled from meta + compute_consumed: None, + success: true, + depth: 0, + }) + .collect(); + + // Extract inner instructions from LiteSVM metadata + let inner_instructions_list = match result { + Ok(meta) => &meta.inner_instructions, + Err(failed) => &failed.meta.inner_instructions, + }; + + // Apply decoder to instructions if enabled and populate inner instructions + let mut instructions = instructions; + if config.decode_light_instructions { + // First, decode all top-level instructions + for instruction in instructions.iter_mut() { + instruction.parsed_data = super::decoder::decode_instruction( + &instruction.program_id, + &instruction.data, + &instruction.accounts, + ); + if let Some(ref parsed) = instruction.parsed_data { + instruction.instruction_name = match parsed { + ParsedInstructionData::LightSystemProgram { + instruction_type, .. + } => Some(instruction_type.clone()), + ParsedInstructionData::ComputeBudget { + instruction_type, .. + } => Some(instruction_type.clone()), + ParsedInstructionData::System { + instruction_type, .. + } => Some(instruction_type.clone()), + _ => None, + }; + } + } + + // Now populate inner instructions for each top-level instruction + for (instruction_index, inner_list) in inner_instructions_list.iter().enumerate() { + if let Some(instruction) = instructions.get_mut(instruction_index) { + instruction.inner_instructions = Self::parse_inner_instructions( + inner_list, // inner_list is already Vec + &transaction.message.account_keys, + &transaction.message, // Pass the full message for account access info + 1, // Start at depth 1 for inner instructions + config, + ); + } + } + } + + // Get LiteSVM's pretty formatted logs + let pretty_logs_string = Self::get_pretty_logs_string(result); + + Self { + signature: *signature, + slot, + status, + fee: estimated_fee, + compute_used: compute_consumed, + compute_total: 1_400_000, // Default compute limit + instructions, + account_changes: Vec::new(), // Will be filled if requested + program_logs_pretty: pretty_logs_string, + light_events: Vec::new(), + } + } + + /// Parse inner instructions from Solana's InnerInstruction format with proper nesting + fn parse_inner_instructions( + inner_instructions: &[InnerInstruction], + account_keys: &[Pubkey], + message: &solana_sdk::message::Message, + base_depth: usize, + config: &EnhancedLoggingConfig, + ) -> Vec { + let mut result = Vec::new(); + + for (index, inner_ix) in inner_instructions.iter().enumerate() { + let program_id = account_keys[inner_ix.instruction.program_id_index as usize]; + let program_name = get_program_name(&program_id); + + let accounts: Vec = inner_ix + .instruction + .accounts + .iter() + .map(|&idx| { + let account_index = idx as usize; + let pubkey = account_keys[account_index]; + + // Get the correct signer and writable information from the original transaction message + let is_signer = message.is_signer(account_index); + let is_writable = message.is_maybe_writable(account_index, None); + + AccountMeta { + pubkey, + is_signer, + is_writable, + } + }) + .collect(); + + let parsed_data = if config.decode_light_instructions { + super::decoder::decode_instruction( + &program_id, + &inner_ix.instruction.data, + &accounts, + ) + } else { + None + }; + + let instruction_name = parsed_data.as_ref().and_then(|parsed| match parsed { + ParsedInstructionData::LightSystemProgram { + instruction_type, .. + } => Some(instruction_type.clone()), + ParsedInstructionData::ComputeBudget { + instruction_type, .. + } => Some(instruction_type.clone()), + ParsedInstructionData::System { + instruction_type, .. + } => Some(instruction_type.clone()), + _ => None, + }); + + // Calculate the actual depth based on stack_height + // stack_height 2 = first level CPI (depth = base_depth + 1) + // stack_height 3 = second level CPI (depth = base_depth + 2), etc. + let instruction_depth = base_depth + (inner_ix.stack_height as usize).saturating_sub(1); + + let instruction_log = EnhancedInstructionLog { + index, + program_id, + program_name, + instruction_name, + accounts, + data: inner_ix.instruction.data.clone(), + parsed_data, + inner_instructions: Vec::new(), + compute_consumed: None, + success: true, // We assume inner instructions succeeded if we're parsing them + depth: instruction_depth, + }; + + // Find the correct parent for this instruction based on stack height + // Stack height 2 = direct CPI, should be at top level + // Stack height 3+ = nested CPI, should be child of previous instruction with stack_height - 1 + if inner_ix.stack_height <= 2 { + // Top-level CPI - add directly to result + result.push(instruction_log); + } else { + // Nested CPI - find the appropriate parent + // We need to traverse the result structure to find the right parent + let target_parent_depth = instruction_depth - 1; + if let Some(parent) = + Self::find_parent_for_instruction(&mut result, target_parent_depth) + { + parent.inner_instructions.push(instruction_log); + } else { + // Fallback: add to top level if we can't find appropriate parent + result.push(instruction_log); + } + } + } + + result + } + + /// Helper function to find the appropriate parent for nested instructions + fn find_parent_for_instruction( + instructions: &mut [EnhancedInstructionLog], + target_depth: usize, + ) -> Option<&mut EnhancedInstructionLog> { + for instruction in instructions.iter_mut().rev() { + if instruction.depth == target_depth { + return Some(instruction); + } + // Recursively search in inner instructions + if let Some(parent) = + Self::find_parent_for_instruction(&mut instruction.inner_instructions, target_depth) + { + return Some(parent); + } + } + None + } +} +/// Get human-readable program name from pubkey +fn get_program_name(program_id: &Pubkey) -> String { + match program_id.to_string().as_str() { + id if id == system_program::ID.to_string() => "System Program".to_string(), + "ComputeBudget111111111111111111111111111111" => "Compute Budget".to_string(), + "SySTEM1eSU2p4BGQfQpimFEWWSC1XDFeun3Nqzz3rT7" => "Light System Program".to_string(), + "compr6CUsB5m2jS4Y3831ztGSTnDpnKJTKS95d64XVq" => "Account Compression".to_string(), + "cTokenmWW8bLPjZEBAUgYy3zKxQZW6VKi7bqNFEVv3m" => "Compressed Token Program".to_string(), + _ => format!("Unknown Program ({})", program_id), + } +} diff --git a/sdk-libs/program-test/src/logging/types.rs:473:15 b/sdk-libs/program-test/src/logging/types.rs:473:15 new file mode 100644 index 0000000000..e69de29bb2 diff --git a/sdk-libs/program-test/src/program_test/config.rs b/sdk-libs/program-test/src/program_test/config.rs index 33d8262b50..aec0faf78c 100644 --- a/sdk-libs/program-test/src/program_test/config.rs +++ b/sdk-libs/program-test/src/program_test/config.rs @@ -9,6 +9,9 @@ use light_prover_client::prover::ProverConfig; use light_registry::protocol_config::state::ProtocolConfig; use solana_sdk::pubkey::Pubkey; +use crate::logging::EnhancedLoggingConfig; + +/// Configuration for Light Program Test #[derive(Debug, Clone)] pub struct ProgramTestConfig { pub additional_programs: Option>, @@ -25,9 +28,16 @@ pub struct ProgramTestConfig { pub v2_state_tree_config: Option, pub v2_address_tree_config: Option, pub skip_protocol_init: bool, + /// Log failed transactions pub log_failed_tx: bool, + /// Disable all logging pub no_logs: bool, + /// Skip startup logs pub skip_startup_logs: bool, + /// Log Light Protocol events (BatchPublicTransactionEvent, etc.) + pub log_light_protocol_events: bool, + /// Enhanced transaction logging configuration + pub enhanced_logging: EnhancedLoggingConfig, } impl ProgramTestConfig { @@ -77,19 +87,17 @@ impl ProgramTestConfig { } } - // TODO: uncomment once batched trees are on devnet. - // #[cfg(not(feature = "devenv"))] - // pub fn default_with_batched_trees() -> Self { - // Self { - // additional_programs: None, - // with_prover: false, - // v2_state_tree_config: Some(InitStateTreeAccountsInstructionData::default()), - // v2_address_tree_config: Some( - // InitAddressTreeAccountsInstructionData::default(), - // ), - // ..Default::default() - // } - // } + /// Enable Light Protocol event logging + pub fn with_light_protocol_events(mut self) -> Self { + self.log_light_protocol_events = true; + self + } + + /// Disable Light Protocol event logging + pub fn without_light_protocol_events(mut self) -> Self { + self.log_light_protocol_events = false; + self + } } impl Default for ProgramTestConfig { @@ -119,6 +127,8 @@ impl Default for ProgramTestConfig { log_failed_tx: true, no_logs: false, skip_startup_logs: true, + log_light_protocol_events: false, // Disabled by default + enhanced_logging: EnhancedLoggingConfig::from_env(), } } } diff --git a/sdk-libs/program-test/src/program_test/light_program_test.rs b/sdk-libs/program-test/src/program_test/light_program_test.rs index 938d071573..04859b74b1 100644 --- a/sdk-libs/program-test/src/program_test/light_program_test.rs +++ b/sdk-libs/program-test/src/program_test/light_program_test.rs @@ -26,6 +26,7 @@ pub struct LightProgramTest { pub indexer: Option, pub test_accounts: TestAccounts, pub payer: Keypair, + pub transaction_counter: usize, } impl LightProgramTest { @@ -58,6 +59,7 @@ impl LightProgramTest { test_accounts: TestAccounts::get_program_test_test_accounts(), payer, config: config.clone(), + transaction_counter: 0, }; let keypairs = TestKeypairs::program_test_default(); diff --git a/sdk-libs/program-test/src/program_test/rpc.rs b/sdk-libs/program-test/src/program_test/rpc.rs index 01821323da..8f92aa3556 100644 --- a/sdk-libs/program-test/src/program_test/rpc.rs +++ b/sdk-libs/program-test/src/program_test/rpc.rs @@ -141,6 +141,9 @@ impl Rpc for LightProgramTest { self._send_transaction_with_batched_event(transaction) .await?; } else { + self.transaction_counter += 1; + let transaction_for_logging = transaction.clone(); + let signature = *transaction.signatures.first().unwrap(); let _res = self.context.send_transaction(transaction).map_err(|x| { if self.config.log_failed_tx { println!("{}", x.meta.pretty_logs()); @@ -148,6 +151,21 @@ impl Rpc for LightProgramTest { RpcError::TransactionError(x.err) })?; + + let slot = self.context.get_sysvar::().slot; + + // Always try enhanced logging for file output (regardless of debug/backtrace settings) + if crate::logging::should_use_enhanced_logging(&self.config) { + crate::logging::log_transaction_enhanced( + &self.config, + &transaction_for_logging, + &Ok(_res.clone()), + &signature, + slot, + self.transaction_counter, + ); + } + self.maybe_print_logs(_res.pretty_logs()); } Ok(sig) @@ -158,15 +176,32 @@ impl Rpc for LightProgramTest { transaction: Transaction, ) -> Result<(Signature, Slot), RpcError> { let sig = *transaction.signatures.first().unwrap(); + self.transaction_counter += 1; + let transaction_for_logging = transaction.clone(); + let signature = *transaction.signatures.first().unwrap(); let _res = self.context.send_transaction(transaction).map_err(|x| { if self.config.log_failed_tx { println!("{}", x.meta.pretty_logs()); } RpcError::TransactionError(x.err) })?; - self.maybe_print_logs(_res.pretty_logs()); let slot = self.context.get_sysvar::().slot; + + // Always try enhanced logging for file output (regardless of debug/backtrace settings) + if crate::logging::should_use_enhanced_logging(&self.config) { + crate::logging::log_transaction_enhanced( + &self.config, + &transaction_for_logging, + &Ok(_res.clone()), + &signature, + slot, + self.transaction_counter, + ); + } + + self.maybe_print_logs(_res.pretty_logs()); + Ok((sig, slot)) } @@ -291,6 +326,13 @@ impl Rpc for LightProgramTest { impl LightProgramTest { fn maybe_print_logs(&self, logs: impl std::fmt::Display) { + // Use enhanced logging if enabled and RUST_BACKTRACE is set + if crate::logging::should_use_enhanced_logging(&self.config) { + // Enhanced logging will be handled in the transaction processing methods + return; + } + + // Fallback to basic logging if !self.config.no_logs && cfg!(debug_assertions) && std::env::var("RUST_BACKTRACE").is_ok() { println!("{}", logs); @@ -314,9 +356,10 @@ impl LightProgramTest { let mut vec = Vec::new(); let signature = transaction.signatures[0]; - // Simulate the transaction. Currently, in banks-client/server, only - // simulations are able to track CPIs. Therefore, simulating is the - // only way to retrieve the event. + let transaction_for_logging = transaction.clone(); // Clone for logging + // Simulate the transaction. Currently, in banks-client/server, only + // simulations are able to track CPIs. Therefore, simulating is the + // only way to retrieve the event. let simulation_result = self .context .simulate_transaction(transaction.clone()) @@ -394,6 +437,7 @@ impl LightProgramTest { }; // Transaction was successful, execute it. + self.transaction_counter += 1; let _res = self.context.send_transaction(transaction).map_err(|x| { // Prevent duplicate prints for failing tx. @@ -403,18 +447,56 @@ impl LightProgramTest { RpcError::TransactionError(x.err) })?; + + let slot = self.context.get_sysvar::().slot; + + // Always try enhanced logging for file output (regardless of debug/backtrace settings) + if crate::logging::should_use_enhanced_logging(&self.config) { + crate::logging::log_transaction_enhanced( + &self.config, + &transaction_for_logging, + &Ok(_res.clone()), + &signature, + slot, + self.transaction_counter, + ); + } + + // Console logging (only in debug builds with backtrace) if !self.config.no_logs { #[cfg(debug_assertions)] { if std::env::var("RUST_BACKTRACE").is_ok() { - // Print all tx logs and events. - println!("{}", _res.pretty_logs()); - println!("event:\n {:?}", event); + // Use enhanced logging for console if enabled and log_events is true + if crate::logging::should_use_enhanced_logging(&self.config) + && self.config.enhanced_logging.log_events + { + // Print enhanced logs to console + crate::logging::log_transaction_enhanced_with_console( + &self.config, + &transaction_for_logging, + &Ok(_res.clone()), + &signature, + slot, + self.transaction_counter, + true, // Enable console output + ); + + if self.config.log_light_protocol_events { + if let Some(ref event_data) = event { + println!("event:\n {:?}", event_data); + } + } + } else { + // Fallback to basic logging + println!("{}", _res.pretty_logs()); + if self.config.log_light_protocol_events { + println!("event:\n {:?}", event); + } + } } } } - - let slot = self.context.get_sysvar::().slot; let event = event.map(|e| (e, signature, slot)); if let Some(indexer) = self.indexer.as_mut() { @@ -466,6 +548,7 @@ impl LightProgramTest { T::try_from_slice(&inner_instruction.instruction.data).ok() }); // If transaction was successful, execute it. + self.transaction_counter += 1; let _res = self.context.send_transaction(transaction).map_err(|x| { if self.config.log_failed_tx { println!("{}", x.meta.pretty_logs()); From 8eefe480cd52ab49385043ddeff3ad4b88563385 Mon Sep 17 00:00:00 2001 From: ananas-block Date: Wed, 6 Aug 2025 14:15:28 +0200 Subject: [PATCH 2/3] fix: logging --- sdk-libs/program-test/Cargo.toml | 1 + sdk-libs/program-test/src/logging/mod.rs | 11 +- .../src/program_test/light_program_test.rs | 2 + sdk-libs/program-test/src/program_test/rpc.rs | 165 +++++++----------- 4 files changed, 76 insertions(+), 103 deletions(-) diff --git a/sdk-libs/program-test/Cargo.toml b/sdk-libs/program-test/Cargo.toml index f7745c9b7a..8ee936eddf 100644 --- a/sdk-libs/program-test/Cargo.toml +++ b/sdk-libs/program-test/Cargo.toml @@ -57,3 +57,4 @@ solana-transaction-status = { workspace = true } bs58 = { workspace = true } light-sdk-types = { workspace = true } tabled = { workspace = true } +chrono = "0.4" diff --git a/sdk-libs/program-test/src/logging/mod.rs b/sdk-libs/program-test/src/logging/mod.rs index 01033d2846..f3dc79b1ec 100644 --- a/sdk-libs/program-test/src/logging/mod.rs +++ b/sdk-libs/program-test/src/logging/mod.rs @@ -25,6 +25,8 @@ use std::{ time::{SystemTime, UNIX_EPOCH}, }; +use chrono; + pub use config::{EnhancedLoggingConfig, LogVerbosity}; pub use formatter::TransactionFormatter; use litesvm::types::TransactionResult; @@ -83,10 +85,15 @@ fn initialize_log_file() { .truncate(true) .open(&log_path) { + // Format timestamp as readable date + let datetime = chrono::DateTime::from_timestamp(timestamp as i64, 0) + .unwrap_or_else(|| chrono::Utc::now()); + let formatted_date = datetime.format("%Y-%m-%d %H:%M:%S UTC"); + let _ = writeln!( file, - "=== Light Program Test Session Started at Unix Timestamp: {} ===\n", - timestamp + "=== Light Program Test Session Started at {} ===\n", + formatted_date ); } }); diff --git a/sdk-libs/program-test/src/program_test/light_program_test.rs b/sdk-libs/program-test/src/program_test/light_program_test.rs index 04859b74b1..3fdd4d7776 100644 --- a/sdk-libs/program-test/src/program_test/light_program_test.rs +++ b/sdk-libs/program-test/src/program_test/light_program_test.rs @@ -114,6 +114,8 @@ impl LightProgramTest { context.set_account(address_queue_pubkey, account); } } + // reset tx counter after program setup. + context.transaction_counter = 0; // Will always start a prover server. #[cfg(feature = "devenv")] let prover_config = if config.prover_config.is_none() { diff --git a/sdk-libs/program-test/src/program_test/rpc.rs b/sdk-libs/program-test/src/program_test/rpc.rs index 8f92aa3556..48c9e817fe 100644 --- a/sdk-libs/program-test/src/program_test/rpc.rs +++ b/sdk-libs/program-test/src/program_test/rpc.rs @@ -138,12 +138,12 @@ impl Rpc for LightProgramTest { ) -> Result { let sig = *transaction.signatures.first().unwrap(); if self.indexer.is_some() { + // Delegate to _send_transaction_with_batched_event which handles counter and logging self._send_transaction_with_batched_event(transaction) .await?; } else { + // Handle transaction directly without logging (logging should be done elsewhere) self.transaction_counter += 1; - let transaction_for_logging = transaction.clone(); - let signature = *transaction.signatures.first().unwrap(); let _res = self.context.send_transaction(transaction).map_err(|x| { if self.config.log_failed_tx { println!("{}", x.meta.pretty_logs()); @@ -152,20 +152,6 @@ impl Rpc for LightProgramTest { RpcError::TransactionError(x.err) })?; - let slot = self.context.get_sysvar::().slot; - - // Always try enhanced logging for file output (regardless of debug/backtrace settings) - if crate::logging::should_use_enhanced_logging(&self.config) { - crate::logging::log_transaction_enhanced( - &self.config, - &transaction_for_logging, - &Ok(_res.clone()), - &signature, - slot, - self.transaction_counter, - ); - } - self.maybe_print_logs(_res.pretty_logs()); } Ok(sig) @@ -177,8 +163,6 @@ impl Rpc for LightProgramTest { ) -> Result<(Signature, Slot), RpcError> { let sig = *transaction.signatures.first().unwrap(); self.transaction_counter += 1; - let transaction_for_logging = transaction.clone(); - let signature = *transaction.signatures.first().unwrap(); let _res = self.context.send_transaction(transaction).map_err(|x| { if self.config.log_failed_tx { println!("{}", x.meta.pretty_logs()); @@ -187,19 +171,6 @@ impl Rpc for LightProgramTest { })?; let slot = self.context.get_sysvar::().slot; - - // Always try enhanced logging for file output (regardless of debug/backtrace settings) - if crate::logging::should_use_enhanced_logging(&self.config) { - crate::logging::log_transaction_enhanced( - &self.config, - &transaction_for_logging, - &Ok(_res.clone()), - &signature, - slot, - self.transaction_counter, - ); - } - self.maybe_print_logs(_res.pretty_logs()); Ok((sig, slot)) @@ -360,17 +331,68 @@ impl LightProgramTest { // Simulate the transaction. Currently, in banks-client/server, only // simulations are able to track CPIs. Therefore, simulating is the // only way to retrieve the event. - let simulation_result = self - .context - .simulate_transaction(transaction.clone()) - .map_err(|x| { - if self.config.log_failed_tx { - println!("{}", x.meta.pretty_logs()); - } + let simulation_result = self.context.simulate_transaction(transaction.clone()); - RpcError::TransactionError(x.err) - })?; + // Transaction was successful, execute it. + self.transaction_counter += 1; + let transaction_result = self.context.send_transaction(transaction.clone()); + let slot = self.context.get_sysvar::().slot; + // Always try enhanced logging for file output (both success and failure) + if crate::logging::should_use_enhanced_logging(&self.config) { + crate::logging::log_transaction_enhanced( + &self.config, + &transaction_for_logging, + &transaction_result, + &signature, + slot, + self.transaction_counter, + ); + } + + // Handle transaction result after logging + let _res = transaction_result.as_ref().map_err(|x| { + // Prevent duplicate prints for failing tx. + if self.config.log_failed_tx { + crate::logging::log_transaction_enhanced_with_console( + &self.config, + &transaction_for_logging, + &transaction_result, + &signature, + slot, + self.transaction_counter, + true, // Enable console output + ); + } + RpcError::TransactionError(x.err.clone()) + })?; + + // Console logging - if RUST_BACKTRACE is set, print to console too + if !self.config.no_logs && std::env::var("RUST_BACKTRACE").is_ok() { + if crate::logging::should_use_enhanced_logging(&self.config) { + // Print enhanced logs to console + crate::logging::log_transaction_enhanced_with_console( + &self.config, + &transaction_for_logging, + &transaction_result, + &signature, + slot, + self.transaction_counter, + true, // Enable console output + ); + + // if self.config.log_light_protocol_events { + // if let Some(ref event_data) = event { + // println!("event:\n {:?}", event_data); + // } + // } + } else { + // Fallback to basic log printing + self.maybe_print_logs(_res.pretty_logs()); + } + } + + let simulation_result = simulation_result.unwrap(); // Try old event deserialization. let event = simulation_result .meta @@ -435,67 +457,8 @@ impl LightProgramTest { ParseIndexerEventError, >(None))? }; - - // Transaction was successful, execute it. - self.transaction_counter += 1; - let _res = self.context.send_transaction(transaction).map_err(|x| { - // Prevent duplicate prints for failing tx. - - if self.config.log_failed_tx { - println!("{}", x.meta.pretty_logs()); - } - - RpcError::TransactionError(x.err) - })?; - - let slot = self.context.get_sysvar::().slot; - - // Always try enhanced logging for file output (regardless of debug/backtrace settings) - if crate::logging::should_use_enhanced_logging(&self.config) { - crate::logging::log_transaction_enhanced( - &self.config, - &transaction_for_logging, - &Ok(_res.clone()), - &signature, - slot, - self.transaction_counter, - ); - } - - // Console logging (only in debug builds with backtrace) - if !self.config.no_logs { - #[cfg(debug_assertions)] - { - if std::env::var("RUST_BACKTRACE").is_ok() { - // Use enhanced logging for console if enabled and log_events is true - if crate::logging::should_use_enhanced_logging(&self.config) - && self.config.enhanced_logging.log_events - { - // Print enhanced logs to console - crate::logging::log_transaction_enhanced_with_console( - &self.config, - &transaction_for_logging, - &Ok(_res.clone()), - &signature, - slot, - self.transaction_counter, - true, // Enable console output - ); - - if self.config.log_light_protocol_events { - if let Some(ref event_data) = event { - println!("event:\n {:?}", event_data); - } - } - } else { - // Fallback to basic logging - println!("{}", _res.pretty_logs()); - if self.config.log_light_protocol_events { - println!("event:\n {:?}", event); - } - } - } - } + if self.config.log_light_protocol_events { + println!("event:\n {:?}", event); } let event = event.map(|e| (e, signature, slot)); From 40c246193187a4a21660372e454fb2790c06258e Mon Sep 17 00:00:00 2001 From: ananas-block Date: Thu, 7 Aug 2025 11:57:23 +0200 Subject: [PATCH 3/3] fix format --- Cargo.lock | 1 + sdk-libs/program-test/src/logging/mod.rs | 5 ++--- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 4ad0ef81bd..35cd740a67 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3553,6 +3553,7 @@ dependencies = [ "borsh 0.10.4", "bs58", "bytemuck", + "chrono", "light-batched-merkle-tree", "light-client", "light-compressed-account", diff --git a/sdk-libs/program-test/src/logging/mod.rs b/sdk-libs/program-test/src/logging/mod.rs index f3dc79b1ec..232b587c33 100644 --- a/sdk-libs/program-test/src/logging/mod.rs +++ b/sdk-libs/program-test/src/logging/mod.rs @@ -26,7 +26,6 @@ use std::{ }; use chrono; - pub use config::{EnhancedLoggingConfig, LogVerbosity}; pub use formatter::TransactionFormatter; use litesvm::types::TransactionResult; @@ -87,9 +86,9 @@ fn initialize_log_file() { { // Format timestamp as readable date let datetime = chrono::DateTime::from_timestamp(timestamp as i64, 0) - .unwrap_or_else(|| chrono::Utc::now()); + .unwrap_or_else(chrono::Utc::now); let formatted_date = datetime.format("%Y-%m-%d %H:%M:%S UTC"); - + let _ = writeln!( file, "=== Light Program Test Session Started at {} ===\n",