Adds force-debug for additional logs (rust-ethereum#174)

* Adds force-debug for additional logs

* Better formatting

* Fixes clippy

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 = [

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",
+]

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

core/src/eval/misc.rs

@@ -6,13 +6,15 @@ 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)
 }
 
 #[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,13 +50,15 @@ 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)
 }
 
 #[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,19 +136,22 @@ 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)
 		} else {
 			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);

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

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",
+]

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