From 19b7cca214fb27e3677110a606c7e9397668753d Mon Sep 17 00:00:00 2001 From: Nicolas Villanueva Date: Mon, 18 Sep 2023 09:55:02 -0700 Subject: [PATCH] feat: add logs for incoming API requests (#118) * feat: add logs for incoming API requests * chore: update unimplemented method log to warning * chore: add trace LogLevel. Update incoming request logs with full params to Trace. Fix unit test. * chore: add Trace log for API responses --- Cargo.lock | 2 +- Cargo.toml | 2 +- src/hardhat.rs | 6 +-- src/logging_middleware.rs | 93 +++++++++++++++++++++++++++++++++++++++ src/main.rs | 11 ++++- src/node.rs | 28 +----------- src/testing.rs | 5 +-- 7 files changed, 111 insertions(+), 36 deletions(-) create mode 100644 src/logging_middleware.rs diff --git a/Cargo.lock b/Cargo.lock index 9d858ba3..161fc88a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1774,7 +1774,7 @@ checksum = "5443807d6dff69373d433ab9ef5378ad8df50ca6298caf15de6e52e24aaf54d5" [[package]] name = "era_test_node" -version = "0.1.0" +version = "0.1.0-alpha.3" dependencies = [ "anyhow", "bigdecimal", diff --git a/Cargo.toml b/Cargo.toml index fe4d552d..911a3fff 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "era_test_node" -version = "0.1.0" +version = "0.1.0-alpha.3" edition = "2018" authors = ["The Matter Labs Team "] homepage = "https://zksync.io/" diff --git a/src/hardhat.rs b/src/hardhat.rs index b63681be..52063870 100644 --- a/src/hardhat.rs +++ b/src/hardhat.rs @@ -239,7 +239,7 @@ mod tests { .hardhat_mine(None, None) .await .expect("hardhat_mine"); - assert_eq!(result, true); + assert!(result); let current_block = node .get_block_by_number(zksync_types::api::BlockNumber::Latest, false) @@ -253,7 +253,7 @@ mod tests { .hardhat_mine(None, None) .await .expect("hardhat_mine"); - assert_eq!(result, true); + assert!(result); let current_block = node .get_block_by_number(zksync_types::api::BlockNumber::Latest, false) @@ -284,7 +284,7 @@ mod tests { .hardhat_mine(Some(U64::from(num_blocks)), Some(U64::from(interval))) .await .expect("hardhat_mine"); - assert_eq!(result, true); + assert!(result); for i in 0..num_blocks { let current_block = node diff --git a/src/logging_middleware.rs b/src/logging_middleware.rs new file mode 100644 index 00000000..b91f6122 --- /dev/null +++ b/src/logging_middleware.rs @@ -0,0 +1,93 @@ +use colored::Colorize; +use futures::Future; +use futures::{future::Either, FutureExt}; +use itertools::Itertools; +use jsonrpc_core::{ + middleware, Call, FutureResponse, Metadata, Middleware, Params, Request, Response, +}; +use log::LevelFilter; + +#[derive(Clone, Debug, Default)] +pub struct Meta(); +impl Metadata for Meta {} + +pub struct LoggingMiddleware { + log_level_filter: LevelFilter, +} + +impl LoggingMiddleware { + pub fn new(log_level_filter: LevelFilter) -> Self { + Self { log_level_filter } + } +} + +/// Logging Middleware for all in-bound requests +/// Logs out incoming requests and their parameters +/// Useful for debugging applications that are pointed at this service +impl Middleware for LoggingMiddleware { + type Future = FutureResponse; + type CallFuture = middleware::NoopCallFuture; + + fn on_request(&self, request: Request, meta: Meta, next: F) -> Either + where + F: FnOnce(Request, Meta) -> X + Send, + X: Future> + Send + 'static, + { + if let Request::Single(Call::MethodCall(method_call)) = &request { + match self.log_level_filter { + LevelFilter::Trace => { + let full_params = match &method_call.params { + Params::Array(values) => { + if values.is_empty() { + String::default() + } else { + format!("with [{}]", values.iter().join(", ")) + } + } + _ => String::default(), + }; + + log::trace!("{} was called {}", method_call.method.cyan(), full_params); + } + _ => { + // Generate truncated params for requests with massive payloads + let truncated_params = match &method_call.params { + Params::Array(values) => { + if values.is_empty() { + String::default() + } else { + format!( + "with [{}]", + values + .iter() + .map(|s| { + let s_str = s.to_string(); + if s_str.len() > 70 { + format!("{:.67}...", s_str) + } else { + s_str + } + }) + .collect::>() + .join(", ") + ) + } + } + _ => String::default(), + }; + + log::info!( + "{} was called {}", + method_call.method.cyan(), + truncated_params + ); + } + } + }; + + Either::Left(Box::pin(next(request, meta).map(move |res| { + log::trace!("API response => {:?}", res); + res + }))) + } +} diff --git a/src/main.rs b/src/main.rs index a9d151d7..fd6e2e31 100644 --- a/src/main.rs +++ b/src/main.rs @@ -5,6 +5,7 @@ use clap::{Parser, Subcommand, ValueEnum}; use configuration_api::ConfigurationApiNamespaceT; use evm::{EvmNamespaceImpl, EvmNamespaceT}; use fork::{ForkDetails, ForkSource}; +use logging_middleware::LoggingMiddleware; use node::ShowCalls; use simplelog::{ ColorChoice, CombinedLogger, ConfigBuilder, LevelFilter, TermLogger, TerminalMode, WriteLogger, @@ -21,6 +22,7 @@ mod fork; mod formatter; mod hardhat; mod http_fork_source; +mod logging_middleware; mod node; mod resolver; mod system_contracts; @@ -46,7 +48,7 @@ use futures::{ future::{self}, FutureExt, }; -use jsonrpc_core::IoHandler; +use jsonrpc_core::MetaIoHandler; use zksync_basic_types::{L2ChainId, H160, H256}; use crate::{configuration_api::ConfigurationApiNamespace, node::TEST_NODE_NETWORK_ID}; @@ -98,10 +100,12 @@ pub const RICH_WALLETS: [(&str, &str); 10] = [ ), ]; +#[allow(clippy::too_many_arguments)] async fn build_json_http< S: std::marker::Sync + std::marker::Send + 'static + ForkSource + std::fmt::Debug, >( addr: SocketAddr, + log_level_filter: LevelFilter, node: InMemoryNode, net: NetNamespace, config_api: ConfigurationApiNamespace, @@ -112,7 +116,7 @@ async fn build_json_http< let (sender, recv) = oneshot::channel::<()>(); let io_handler = { - let mut io = IoHandler::new(); + let mut io = MetaIoHandler::with_middleware(LoggingMiddleware::new(log_level_filter)); io.extend_with(node.to_delegate()); io.extend_with(net.to_delegate()); io.extend_with(config_api.to_delegate()); @@ -145,6 +149,7 @@ async fn build_json_http< /// Log filter level for the node. #[derive(Debug, Clone, ValueEnum)] enum LogLevel { + Trace, Debug, Info, Warn, @@ -154,6 +159,7 @@ enum LogLevel { impl From for LevelFilter { fn from(value: LogLevel) -> Self { match value { + LogLevel::Trace => LevelFilter::Trace, LogLevel::Debug => LevelFilter::Debug, LogLevel::Info => LevelFilter::Info, LogLevel::Warn => LevelFilter::Warn, @@ -368,6 +374,7 @@ async fn main() -> anyhow::Result<()> { let threads = build_json_http( SocketAddr::new(IpAddr::V4(Ipv4Addr::new(0, 0, 0, 0)), opt.port), + log_level_filter, node, net, config_api, diff --git a/src/node.rs b/src/node.rs index 95581ac4..e7d3553a 100644 --- a/src/node.rs +++ b/src/node.rs @@ -562,7 +562,7 @@ impl InMemoryNodeInner { fn not_implemented( method_name: &str, ) -> jsonrpc_core::BoxFuture> { - log::info!("Method {} is not implemented", method_name); + log::warn!("Method {} is not implemented", method_name); Err(jsonrpc_core::Error { data: None, code: jsonrpc_core::ErrorCode::MethodNotFound, @@ -2120,31 +2120,7 @@ mod tests { async fn test_get_fee_history_with_multiple_blocks() { // Arrange let node = InMemoryNode::::default(); - - let private_key = H256::random(); - let from_account = PackedEthSignature::address_from_private_key(&private_key) - .expect("failed generating address"); - node.set_rich_account(from_account); - let mut tx = L2Tx::new_signed( - Address::random(), - vec![], - Nonce(0), - Fee { - gas_limit: U256::from(1_000_000), - max_fee_per_gas: U256::from(250_000_000), - max_priority_fee_per_gas: U256::from(250_000_000), - gas_per_pubdata_limit: U256::from(20000), - }, - U256::from(1), - L2ChainId(260), - &private_key, - None, - Default::default(), - ) - .unwrap(); - tx.set_input(vec![], H256::repeat_byte(0x01)); - - node.apply_txs(vec![tx]).expect("failed applying tx"); + testing::apply_tx(&node, H256::repeat_byte(0x01)); // Act let fee_history = node diff --git a/src/testing.rs b/src/testing.rs index 24f6dc8c..7fd03227 100644 --- a/src/testing.rs +++ b/src/testing.rs @@ -124,7 +124,6 @@ impl MockServer { "sealFields": [], "uncles": [], "transactions": (0..block_config.transaction_count) - .into_iter() .map(|index| { TransactionResponseBuilder::new() .set_hash(H256::repeat_byte(index)) @@ -381,7 +380,7 @@ pub fn apply_tx(node: &InMemoryNode, tx_hash ) .unwrap(); tx.set_input(vec![], tx_hash); - node.apply_txs(vec![tx.into()]).expect("failed applying tx"); + node.apply_txs(vec![tx]).expect("failed applying tx"); produced_block_hash } @@ -463,7 +462,7 @@ mod test { .as_object() .and_then(|o| o.get("result").unwrap().as_array()) .map(|o| { - o.into_iter() + o.iter() .map(|o| o.get("common_data").unwrap().as_object().unwrap()) .map(|o| o.get("L1").unwrap().as_object().unwrap()) .map(|entry| entry.get("serialId").unwrap().as_u64().unwrap())