From a33ac87ad7462b7e7029d12c385492b2a8311d1c Mon Sep 17 00:00:00 2001 From: Alan Sapede Date: Mon, 28 Aug 2023 16:56:38 +0200 Subject: [PATCH] Adds force-debug for additional logs (#174) * Adds force-debug for additional logs * Better formatting * Fixes clippy --- Cargo.toml | 4 ++++ core/Cargo.toml | 4 ++++ core/src/eval/macros.rs | 16 +++++++++++++ core/src/eval/misc.rs | 19 ++++++++++++++- core/src/lib.rs | 3 +++ gasometer/Cargo.toml | 5 ++++ gasometer/src/lib.rs | 51 +++++++++++++++++++++++++++++++++++++++-- 7 files changed, 99 insertions(+), 3 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 829eea0e0..66ad0a075 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -69,6 +69,10 @@ tracing = [ "evm-gasometer/tracing", "evm-runtime/tracing", ] +force-debug = [ + "evm-core/force-debug", + "evm-gasometer/force-debug", +] [workspace] members = [ diff --git a/core/Cargo.toml b/core/Cargo.toml index 3b5618cd5..5c368e72e 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -9,6 +9,7 @@ keywords = ["no_std", "ethereum"] edition = "2018" [dependencies] +log = { version = "0.4", optional = true } primitive-types = { version = "0.12", default-features = false } scale-codec = { package = "parity-scale-codec", version = "3.2", default-features = false, features = ["derive", "full"], optional = true } scale-info = { version = "2.3", default-features = false, features = ["derive"], optional = true } @@ -34,3 +35,6 @@ with-serde = [ "serde", "primitive-types/impl-serde", ] +force-debug = [ + "log", +] \ No newline at end of file diff --git a/core/src/eval/macros.rs b/core/src/eval/macros.rs index 3fd7a9f6e..1e1533a93 100644 --- a/core/src/eval/macros.rs +++ b/core/src/eval/macros.rs @@ -1,3 +1,13 @@ +#[cfg(feature = "force-debug")] +macro_rules! trace_op { + ($($arg:tt)*) => (log::trace!(target: "evm", "OpCode {}", format_args!($($arg)*))); +} + +#[cfg(not(feature = "force-debug"))] +macro_rules! trace_op { + ($($arg:tt)*) => {}; +} + macro_rules! try_or_fail { ( $e:expr ) => { match $e { @@ -58,6 +68,7 @@ macro_rules! op1_u256_fn { pop_u256!($machine, op1); let ret = $op(op1); push_u256!($machine, ret); + trace_op!("{} {}: {}", stringify!($op), op1, ret); Control::Continue(1) }}; @@ -68,6 +79,7 @@ macro_rules! op2_u256_bool_ref { pop_u256!($machine, op1, op2); let ret = op1.$op(&op2); push_u256!($machine, if ret { U256::one() } else { U256::zero() }); + trace_op!("{} {}, {}: {}", stringify!($op), op1, op2, ret); Control::Continue(1) }}; @@ -78,6 +90,7 @@ macro_rules! op2_u256 { pop_u256!($machine, op1, op2); let ret = op1.$op(op2); push_u256!($machine, ret); + trace_op!("{} {}, {}: {}", stringify!($op), op1, op2, ret); Control::Continue(1) }}; @@ -88,6 +101,7 @@ macro_rules! op2_u256_tuple { pop_u256!($machine, op1, op2); let (ret, ..) = op1.$op(op2); push_u256!($machine, ret); + trace_op!("{} {}, {}: {}", stringify!($op), op1, op2, ret); Control::Continue(1) }}; @@ -98,6 +112,7 @@ macro_rules! op2_u256_fn { pop_u256!($machine, op1, op2); let ret = $op(op1, op2); push_u256!($machine, ret); + trace_op!("{} {}, {}: {}", stringify!($op), op1, op2, ret); Control::Continue(1) }}; @@ -108,6 +123,7 @@ macro_rules! op3_u256_fn { pop_u256!($machine, op1, op2, op3); let ret = $op(op1, op2, op3); push_u256!($machine, ret); + trace_op!("{} {}, {}, {}: {}", stringify!($op), op1, op2, op3, ret); Control::Continue(1) }}; diff --git a/core/src/eval/misc.rs b/core/src/eval/misc.rs index 8271d5f6c..398bcc34c 100644 --- a/core/src/eval/misc.rs +++ b/core/src/eval/misc.rs @@ -6,6 +6,7 @@ use primitive_types::{H256, U256}; #[inline] pub fn codesize(state: &mut Machine) -> Control { let size = U256::from(state.code.len()); + trace_op!("CodeSize: {}", size); push_u256!(state, size); Control::Continue(1) } @@ -13,6 +14,7 @@ pub fn codesize(state: &mut Machine) -> Control { #[inline] pub fn codecopy(state: &mut Machine) -> Control { pop_u256!(state, memory_offset, code_offset, len); + trace_op!("CodeCopy: {}", len); try_or_fail!(state.memory.resize_offset(memory_offset, len)); match state @@ -48,6 +50,7 @@ pub fn calldataload(state: &mut Machine) -> Control { #[inline] pub fn calldatasize(state: &mut Machine) -> Control { let len = U256::from(state.data.len()); + trace_op!("CallDataSize: {}", len); push_u256!(state, len); Control::Continue(1) } @@ -55,6 +58,7 @@ pub fn calldatasize(state: &mut Machine) -> Control { #[inline] pub fn calldatacopy(state: &mut Machine) -> Control { pop_u256!(state, memory_offset, data_offset, len); + trace_op!("CallDataCopy: {}", len); try_or_fail!(state.memory.resize_offset(memory_offset, len)); if len == U256::zero() { @@ -73,12 +77,14 @@ pub fn calldatacopy(state: &mut Machine) -> Control { #[inline] pub fn pop(state: &mut Machine) -> Control { pop!(state, _val); + trace_op!("Pop [@{}]: {}", state.stack.len(), _val); Control::Continue(1) } #[inline] pub fn mload(state: &mut Machine) -> Control { pop_u256!(state, index); + trace_op!("MLoad: {}", index); try_or_fail!(state.memory.resize_offset(index, U256::from(32))); let index = as_usize_or_fail!(index); let value = H256::from_slice(&state.memory.get(index, 32)[..]); @@ -90,6 +96,7 @@ pub fn mload(state: &mut Machine) -> Control { pub fn mstore(state: &mut Machine) -> Control { pop_u256!(state, index); pop!(state, value); + trace_op!("MStore: {}, {}", index, value); try_or_fail!(state.memory.resize_offset(index, U256::from(32))); let index = as_usize_or_fail!(index); match state.memory.set(index, &value[..], Some(32)) { @@ -114,6 +121,7 @@ pub fn mstore8(state: &mut Machine) -> Control { pub fn jump(state: &mut Machine) -> Control { pop_u256!(state, dest); let dest = as_usize_or_fail!(dest, ExitError::InvalidJump); + trace_op!("Jump: {}", dest); if state.valids.is_valid(dest) { Control::Jump(dest) @@ -128,6 +136,7 @@ pub fn jumpi(state: &mut Machine) -> Control { pop!(state, value); if value != H256::zero() { + trace_op!("JumpI: {}", dest); let dest = as_usize_or_fail!(dest, ExitError::InvalidJump); if state.valids.is_valid(dest) { Control::Jump(dest) @@ -135,12 +144,14 @@ pub fn jumpi(state: &mut Machine) -> Control { Control::Exit(ExitError::InvalidJump.into()) } } else { + trace_op!("JumpI: skipped"); Control::Continue(1) } } #[inline] pub fn pc(state: &mut Machine, position: usize) -> Control { + trace_op!("PC"); push_u256!(state, U256::from(position)); Control::Continue(1) } @@ -158,7 +169,9 @@ pub fn push(state: &mut Machine, n: usize, position: usize) -> Control { let mut val = [0u8; 32]; val[(32 - n)..(32 - n + slice.len())].copy_from_slice(slice); - push!(state, H256(val)); + let result = H256(val); + push!(state, result); + trace_op!("Push [@{}]: {}", state.stack.len() - 1, result); Control::Continue(1 + n) } @@ -168,6 +181,7 @@ pub fn dup(state: &mut Machine, n: usize) -> Control { Ok(value) => value, Err(e) => return Control::Exit(e.into()), }; + trace_op!("Dup{} [@{}]: {}", n, state.stack.len(), value); push!(state, value); Control::Continue(1) } @@ -190,11 +204,13 @@ pub fn swap(state: &mut Machine, n: usize) -> Control { Ok(()) => (), Err(e) => return Control::Exit(e.into()), } + trace_op!("Swap [@0:@{}]: {}, {}", n, val1, val2); Control::Continue(1) } #[inline] pub fn ret(state: &mut Machine) -> Control { + trace_op!("Return"); pop_u256!(state, start, len); try_or_fail!(state.memory.resize_offset(start, len)); state.return_range = start..(start + len); @@ -203,6 +219,7 @@ pub fn ret(state: &mut Machine) -> Control { #[inline] pub fn revert(state: &mut Machine) -> Control { + trace_op!("Revert"); pop_u256!(state, start, len); try_or_fail!(state.memory.resize_offset(start, len)); state.return_range = start..(start + len); diff --git a/core/src/lib.rs b/core/src/lib.rs index 20e8fc053..53aafc364 100644 --- a/core/src/lib.rs +++ b/core/src/lib.rs @@ -161,6 +161,9 @@ impl Machine { Ok(()) } Control::Trap(opcode) => { + #[cfg(feature = "force-debug")] + log::trace!(target: "evm", "OpCode Trap: {:?}", opcode); + self.position = Ok(position + 1); Err(Capture::Trap(opcode)) } diff --git a/gasometer/Cargo.toml b/gasometer/Cargo.toml index 4bf14bcf5..d6d63fe8e 100644 --- a/gasometer/Cargo.toml +++ b/gasometer/Cargo.toml @@ -10,6 +10,7 @@ edition = "2018" [dependencies] environmental = { version = "1.1.2", default-features = false, optional = true } +log = { version = "0.4", optional = true } primitive-types = { version = "0.12", default-features = false } evm-core = { version = "0.39", path = "../core", default-features = false } @@ -26,3 +27,7 @@ std = [ tracing = [ "environmental", ] + +force-debug = [ + "log", +] \ No newline at end of file diff --git a/gasometer/src/lib.rs b/gasometer/src/lib.rs index fe57722ad..8e4e6a143 100644 --- a/gasometer/src/lib.rs +++ b/gasometer/src/lib.rs @@ -16,6 +16,16 @@ macro_rules! event { crate::tracing::with(|listener| listener.event($x)); }; } +#[cfg(feature = "force-debug")] +macro_rules! log_gas { + ($self:expr, $($arg:tt)*) => (log::trace!(target: "evm", "Gasometer {} [Gas used: {}, Gas left: {}]", format_args!($($arg)*), + $self.total_used_gas(), $self.gas())); +} + +#[cfg(not(feature = "force-debug"))] +macro_rules! log_gas { + ($self:expr, $($arg:tt)*) => {}; +} #[cfg(not(feature = "tracing"))] macro_rules! event { @@ -137,6 +147,7 @@ impl<'config> Gasometer<'config> { cost, snapshot: self.snapshot(), }); + log_gas!(self, "Record cost {}", cost); let all_gas_cost = self.total_used_gas() + cost; if self.gas_limit < all_gas_cost { @@ -155,6 +166,7 @@ impl<'config> Gasometer<'config> { refund, snapshot: self.snapshot(), }); + log_gas!(self, "Record refund -{}", refund); self.inner_mut()?.refunded_gas += refund; Ok(()) @@ -196,6 +208,14 @@ impl<'config> Gasometer<'config> { return Err(ExitError::OutOfGas); } + log_gas!( + self, + "Record dynamic cost {} - memory_gas {} - gas_refund {}", + gas_cost, + memory_gas, + gas_refund + ); + let after_gas = self.gas_limit - all_gas_cost; try_or_fail!(self.inner, self.inner_mut()?.extra_check(cost, after_gas)); @@ -215,6 +235,7 @@ impl<'config> Gasometer<'config> { }); self.inner_mut()?.used_gas -= stipend; + log_gas!(self, "Record stipent {}", stipend); Ok(()) } @@ -227,11 +248,25 @@ impl<'config> Gasometer<'config> { access_list_address_len, access_list_storage_len, } => { - self.config.gas_transaction_call + #[deny(clippy::let_and_return)] + let cost = self.config.gas_transaction_call + zero_data_len as u64 * self.config.gas_transaction_zero_data + non_zero_data_len as u64 * self.config.gas_transaction_non_zero_data + access_list_address_len as u64 * self.config.gas_access_list_address - + access_list_storage_len as u64 * self.config.gas_access_list_storage_key + + access_list_storage_len as u64 * self.config.gas_access_list_storage_key; + + log_gas!( + self, + "Record Call {} [gas_transaction_call: {}, zero_data_len: {}, non_zero_data_len: {}, access_list_address_len: {}, access_list_storage_len: {}]", + cost, + self.config.gas_transaction_call, + zero_data_len, + non_zero_data_len, + access_list_address_len, + access_list_storage_len + ); + + cost } TransactionCost::Create { zero_data_len, @@ -248,6 +283,18 @@ impl<'config> Gasometer<'config> { if self.config.max_initcode_size.is_some() { cost += initcode_cost; } + + log_gas!( + self, + "Record Create {} [gas_transaction_create: {}, zero_data_len: {}, non_zero_data_len: {}, access_list_address_len: {}, access_list_storage_len: {}, initcode_cost: {}]", + cost, + self.config.gas_transaction_create, + zero_data_len, + non_zero_data_len, + access_list_address_len, + access_list_storage_len, + initcode_cost + ); cost } };