gaspersic/solana
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Refactor: Cleanup program-runtime dyn Traits (#21395)

Browse Source 
* Unifies dyn Trait ComputeMeter, ThisComputeMeter and TransactionComputeMeter.

* Unifies dyn Trait Logger and ThisLogger.

* Moves Logger to log_collector.rs

* Unifies Logger and LogCollector.

* Removes inner RefCell from LogCollector.

* Adds the log::debug!() message to ic_logger_msg!() again.
This commit is contained in:
Alexander Meißner
2021-11-23 13:23:40 +01:00
committed by GitHub
parent cd5a39ee43
commit 22a2537aac
9 changed files with 302 additions and 340 deletions
Download Patch File Download Diff File Expand all files Collapse all files

122
program-runtime/src/invoke_context.rs
View File

@ -4,7 +4,6 @@ use crate::{
instruction_recorder::InstructionRecorder,
log_collector::LogCollector,
};
use log::*;
use solana_sdk::{
account::{AccountSharedData, ReadableAccount},
compute_budget::ComputeBudget,
@ -23,18 +22,12 @@ use solana_sdk::{
use std::{cell::RefCell, rc::Rc, sync::Arc};
/// Compute meter
pub trait ComputeMeter {
/// Consume compute units
fn consume(&mut self, amount: u64) -> Result<(), InstructionError>;
/// Get the number of remaining compute units
fn get_remaining(&self) -> u64;
}
pub struct ThisComputeMeter {
pub struct ComputeMeter {
remaining: u64,
}
impl ComputeMeter for ThisComputeMeter {
fn consume(&mut self, amount: u64) -> Result<(), InstructionError> {
impl ComputeMeter {
/// Consume compute units
pub fn consume(&mut self, amount: u64) -> Result<(), InstructionError> {
let exceeded = self.remaining < amount;
self.remaining = self.remaining.saturating_sub(amount);
if exceeded {
@ -42,77 +35,16 @@ impl ComputeMeter for ThisComputeMeter {
}
Ok(())
}
fn get_remaining(&self) -> u64 {
/// Get the number of remaining compute units
pub fn get_remaining(&self) -> u64 {
self.remaining
}
}
impl ThisComputeMeter {
/// Construct a new one with the given remaining units
pub fn new_ref(remaining: u64) -> Rc<RefCell<Self>> {
Rc::new(RefCell::new(Self { remaining }))
}
}
/// Log messages
pub trait Logger {
fn log_enabled(&self) -> bool;
/// Log a message.
///
/// Unless explicitly stated, log messages are not considered stable and may change in the
/// future as necessary
fn log(&self, message: &str);
}
pub struct ThisLogger {
log_collector: Option<Rc<LogCollector>>,
}
impl Logger for ThisLogger {
fn log_enabled(&self) -> bool {
log_enabled!(log::Level::Info) || self.log_collector.is_some()
}
fn log(&self, message: &str) {
debug!("{}", message);
if let Some(log_collector) = &self.log_collector {
log_collector.log(message);
}
}
}
impl ThisLogger {
pub fn new_ref(log_collector: Option<Rc<LogCollector>>) -> Rc<RefCell<Self>> {
Rc::new(RefCell::new(Self { log_collector }))
}
}
/// Convenience macro to log a message with an `Rc<RefCell<dyn Logger>>`
#[macro_export]
macro_rules! ic_logger_msg {
($logger:expr, $message:expr) => {
if let Ok(logger) = $logger.try_borrow_mut() {
if logger.log_enabled() {
logger.log($message);
}
}
};
($logger:expr, $fmt:expr, $($arg:tt)*) => {
if let Ok(logger) = $logger.try_borrow_mut() {
if logger.log_enabled() {
logger.log(&format!($fmt, $($arg)*));
}
}
};
}
/// Convenience macro to log a message with an `InvokeContext`
#[macro_export]
macro_rules! ic_msg {
($invoke_context:expr, $message:expr) => {
$crate::ic_logger_msg!($invoke_context.get_logger(), $message)
};
($invoke_context:expr, $fmt:expr, $($arg:tt)*) => {
$crate::ic_logger_msg!($invoke_context.get_logger(), $fmt, $($arg)*)
};
}
pub struct InvokeContextStackFrame<'a> {
pub number_of_program_accounts: usize,
pub keyed_accounts: Vec<KeyedAccount<'a>>,
@ -147,10 +79,10 @@ pub struct ThisInvokeContext<'a> {
accounts: &'a [(Pubkey, Rc<RefCell<AccountSharedData>>)],
programs: &'a [(Pubkey, ProcessInstructionWithContext)],
sysvars: &'a [(Pubkey, Vec<u8>)],
logger: Rc<RefCell<dyn Logger>>,
log_collector: Option<Rc<RefCell<LogCollector>>>,
compute_budget: ComputeBudget,
current_compute_budget: ComputeBudget,
compute_meter: Rc<RefCell<dyn ComputeMeter>>,
compute_meter: Rc<RefCell<ComputeMeter>>,
executors: Rc<RefCell<Executors>>,
instruction_recorders: Option<&'a [InstructionRecorder]>,
feature_set: Arc<FeatureSet>,
@ -166,9 +98,9 @@ impl<'a> ThisInvokeContext<'a> {
accounts: &'a [(Pubkey, Rc<RefCell<AccountSharedData>>)],
programs: &'a [(Pubkey, ProcessInstructionWithContext)],
sysvars: &'a [(Pubkey, Vec<u8>)],
log_collector: Option<Rc<LogCollector>>,
log_collector: Option<Rc<RefCell<LogCollector>>>,
compute_budget: ComputeBudget,
compute_meter: Rc<RefCell<dyn ComputeMeter>>,
compute_meter: Rc<RefCell<ComputeMeter>>,
executors: Rc<RefCell<Executors>>,
instruction_recorders: Option<&'a [InstructionRecorder]>,
feature_set: Arc<FeatureSet>,
@ -183,7 +115,7 @@ impl<'a> ThisInvokeContext<'a> {
accounts,
programs,
sysvars,
logger: ThisLogger::new_ref(log_collector),
log_collector,
current_compute_budget: compute_budget,
compute_budget,
compute_meter,
@ -210,7 +142,7 @@ impl<'a> ThisInvokeContext<'a> {
sysvars,
None,
ComputeBudget::default(),
ThisComputeMeter::new_ref(std::i64::MAX as u64),
ComputeMeter::new_ref(std::i64::MAX as u64),
Rc::new(RefCell::new(Executors::default())),
None,
feature_set,
@ -272,10 +204,10 @@ pub trait InvokeContext {
fn get_keyed_accounts(&self) -> Result<&[KeyedAccount], InstructionError>;
/// Get a list of built-in programs
fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)];
/// Get this invocation's logger
fn get_logger(&self) -> Rc<RefCell<dyn Logger>>;
/// Get this invocation's compute meter
fn get_compute_meter(&self) -> Rc<RefCell<dyn ComputeMeter>>;
/// Get this invocation's LogCollector
fn get_log_collector(&self) -> Option<Rc<RefCell<LogCollector>>>;
/// Get this invocation's ComputeMeter
fn get_compute_meter(&self) -> Rc<RefCell<ComputeMeter>>;
/// Loaders may need to do work in order to execute a program. Cache
/// the work that can be re-used across executions
fn add_executor(&self, pubkey: &Pubkey, executor: Arc<dyn Executor>);
@ -349,8 +281,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
self.current_compute_budget = compute_budget;
if !self.feature_set.is_active(&tx_wide_compute_cap::id()) {
self.compute_meter =
ThisComputeMeter::new_ref(self.current_compute_budget.max_units);
self.compute_meter = ComputeMeter::new_ref(self.current_compute_budget.max_units);
}
self.pre_accounts = Vec::with_capacity(instruction.accounts.len());
@ -464,7 +395,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
)
.map_err(|err| {
ic_logger_msg!(
self.logger,
self.log_collector,
"failed to verify account {}: {}",
pre_account.key(),
err
@ -500,7 +431,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
.and_then(|frame| frame.program_id())
.ok_or(InstructionError::CallDepth)?;
let rent = &self.rent;
let logger = &self.logger;
let log_collector = &self.log_collector;
let accounts = &self.accounts;
let pre_accounts = &mut self.pre_accounts;
let timings = &mut self.timings;
@ -535,7 +466,12 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
do_support_realloc,
)
.map_err(|err| {
ic_logger_msg!(logger, "failed to verify account {}: {}", key, err);
ic_logger_msg!(
log_collector,
"failed to verify account {}: {}",
key,
err
);
err
})?;
pre_sum = pre_sum
@ -587,10 +523,10 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> {
fn get_programs(&self) -> &[(Pubkey, ProcessInstructionWithContext)] {
self.programs
}
fn get_logger(&self) -> Rc<RefCell<dyn Logger>> {
self.logger.clone()
fn get_log_collector(&self) -> Option<Rc<RefCell<LogCollector>>> {
self.log_collector.clone()
}
fn get_compute_meter(&self) -> Rc<RefCell<dyn ComputeMeter>> {
fn get_compute_meter(&self) -> Rc<RefCell<ComputeMeter>> {
self.compute_meter.clone()
}
fn add_executor(&self, pubkey: &Pubkey, executor: Arc<dyn Executor>) {

65
program-runtime/src/log_collector.rs
View File

@ -1,48 +1,79 @@
use std::cell::RefCell;
pub use log;
use std::{cell::RefCell, rc::Rc};
const LOG_MESSAGES_BYTES_LIMIT: usize = 10 * 1000;
#[derive(Default)]
struct LogCollectorInner {
pub struct LogCollector {
messages: Vec<String>,
bytes_written: usize,
limit_warning: bool,
}
#[derive(Default)]
pub struct LogCollector {
inner: RefCell<LogCollectorInner>,
}
impl LogCollector {
pub fn log(&self, message: &str) {
let mut inner = self.inner.borrow_mut();
let bytes_written = inner.bytes_written.saturating_add(message.len());
pub fn log(&mut self, message: &str) {
let bytes_written = self.bytes_written.saturating_add(message.len());
if bytes_written >= LOG_MESSAGES_BYTES_LIMIT {
if !inner.limit_warning {
inner.limit_warning = true;
inner.messages.push(String::from("Log truncated"));
if !self.limit_warning {
self.limit_warning = true;
self.messages.push(String::from("Log truncated"));
}
} else {
inner.bytes_written = bytes_written;
inner.messages.push(message.to_string());
self.bytes_written = bytes_written;
self.messages.push(message.to_string());
}
}
pub fn new_ref() -> Rc<RefCell<Self>> {
Rc::new(RefCell::new(Self::default()))
}
}
impl From<LogCollector> for Vec<String> {
fn from(log_collector: LogCollector) -> Self {
log_collector.inner.into_inner().messages
log_collector.messages
}
}
/// Convenience macro to log a message with an `Option<Rc<RefCell<LogCollector>>>`
#[macro_export]
macro_rules! ic_logger_msg {
($log_collector:expr, $message:expr) => {
$crate::log_collector::log::debug!("{}", $message);
if let Some(log_collector) = $log_collector.as_ref() {
if let Ok(mut log_collector) = log_collector.try_borrow_mut() {
log_collector.log($message);
}
}
};
($log_collector:expr, $fmt:expr, $($arg:tt)*) => {
$crate::log_collector::log::debug!($fmt, $($arg)*);
if let Some(log_collector) = $log_collector.as_ref() {
if let Ok(mut log_collector) = log_collector.try_borrow_mut() {
log_collector.log(&format!($fmt, $($arg)*));
}
}
};
}
/// Convenience macro to log a message with an `InvokeContext`
#[macro_export]
macro_rules! ic_msg {
($invoke_context:expr, $message:expr) => {
$crate::ic_logger_msg!($invoke_context.get_log_collector(), $message)
};
($invoke_context:expr, $fmt:expr, $($arg:tt)*) => {
$crate::ic_logger_msg!($invoke_context.get_log_collector(), $fmt, $($arg)*)
};
}
#[cfg(test)]
pub(crate) mod tests {
use super::*;
#[test]
fn test_log_messages_bytes_limit() {
let lc = LogCollector::default();
let mut lc = LogCollector::default();
for _i in 0..LOG_MESSAGES_BYTES_LIMIT * 2 {
lc.log("x");

39
program-runtime/src/stable_log.rs
View File

@ -2,7 +2,7 @@
//!
//! The format of these log messages should not be modified to avoid breaking downstream consumers
//! of program logging
use crate::{ic_logger_msg, invoke_context::Logger};
use crate::{ic_logger_msg, log_collector::LogCollector};
use itertools::Itertools;
use solana_sdk::{instruction::InstructionError, pubkey::Pubkey};
use std::{cell::RefCell, rc::Rc};
@ -14,8 +14,17 @@ use std::{cell::RefCell, rc::Rc};
/// ```notrust
/// "Program <address> invoke [<depth>]"
/// ```
pub fn program_invoke(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey, invoke_depth: usize) {
ic_logger_msg!(logger, "Program {} invoke [{}]", program_id, invoke_depth);
pub fn program_invoke(
log_collector: &Option<Rc<RefCell<LogCollector>>>,
program_id: &Pubkey,
invoke_depth: usize,
) {
ic_logger_msg!(
log_collector,
"Program {} invoke [{}]",
program_id,
invoke_depth
);
}
/// Log a message from the program itself.
@ -27,8 +36,8 @@ pub fn program_invoke(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey, inv
/// ```
///
/// That is, any program-generated output is guaranteed to be prefixed by "Program log: "
pub fn program_log(logger: &Rc<RefCell<dyn Logger>>, message: &str) {
ic_logger_msg!(logger, "Program log: {}", message);
pub fn program_log(log_collector: &Option<Rc<RefCell<LogCollector>>>, message: &str) {
ic_logger_msg!(log_collector, "Program log: {}", message);
}
/// Emit a program data.
@ -40,9 +49,9 @@ pub fn program_log(logger: &Rc<RefCell<dyn Logger>>, message: &str) {
/// ```
///
/// That is, any program-generated output is guaranteed to be prefixed by "Program data: "
pub fn program_data(logger: &Rc<RefCell<dyn Logger>>, data: &[&[u8]]) {
pub fn program_data(log_collector: &Option<Rc<RefCell<LogCollector>>>, data: &[&[u8]]) {
ic_logger_msg!(
logger,
log_collector,
"Program data: {}",
data.iter().map(base64::encode).join(" ")
);
@ -58,9 +67,13 @@ pub fn program_data(logger: &Rc<RefCell<dyn Logger>>, data: &[&[u8]]) {
/// ```
///
/// That is, any program-generated output is guaranteed to be prefixed by "Program return: "
pub fn program_return(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey, data: &[u8]) {
pub fn program_return(
log_collector: &Option<Rc<RefCell<LogCollector>>>,
program_id: &Pubkey,
data: &[u8],
) {
ic_logger_msg!(
logger,
log_collector,
"Program return: {} {}",
program_id,
base64::encode(data)
@ -74,8 +87,8 @@ pub fn program_return(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey, dat
/// ```notrust
/// "Program <address> success"
/// ```
pub fn program_success(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey) {
ic_logger_msg!(logger, "Program {} success", program_id);
pub fn program_success(log_collector: &Option<Rc<RefCell<LogCollector>>>, program_id: &Pubkey) {
ic_logger_msg!(log_collector, "Program {} success", program_id);
}
/// Log program execution failure
@ -86,9 +99,9 @@ pub fn program_success(logger: &Rc<RefCell<dyn Logger>>, program_id: &Pubkey) {
/// "Program <address> failed: <program error details>"
/// ```
pub fn program_failure(
logger: &Rc<RefCell<dyn Logger>>,
log_collector: &Option<Rc<RefCell<LogCollector>>>,
program_id: &Pubkey,
err: &InstructionError,
) {
ic_logger_msg!(logger, "Program {} failed: {}", program_id, err);
ic_logger_msg!(log_collector, "Program {} failed: {}", program_id, err);
}