From c637672b3e2b85a1e91787b3a9565dcab464880b Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Fri, 15 Sep 2023 18:04:05 +0100 Subject: [PATCH 1/8] feat: add logs for incoming API requests --- Cargo.lock | 2 +- Cargo.toml | 2 +- src/logging_middleware.rs | 99 +++++++++++++++++++++++++++++++++++++++ src/main.rs | 10 ++-- src/node.rs | 2 +- 5 files changed, 109 insertions(+), 6 deletions(-) create mode 100644 src/logging_middleware.rs diff --git a/Cargo.lock b/Cargo.lock index 44d9e2eb..5df32fcb 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 2c02e1da..986b9a00 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/logging_middleware.rs b/src/logging_middleware.rs new file mode 100644 index 00000000..01c8edc4 --- /dev/null +++ b/src/logging_middleware.rs @@ -0,0 +1,99 @@ +use colored::Colorize; +use itertools::Itertools; +use jsonrpc_core::{Middleware, Metadata, Request, Response, middleware, FutureResponse, Call, Params}; +use futures::future::Either; +use futures::Future; +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, + { + match &request { + Request::Single(call) => { + match call { + Call::MethodCall(method_call) => { + match self.log_level_filter { + LevelFilter::Debug => { + let full_params = match &method_call.params { + Params::Array(values) => { + if values.len() == 0 { + String::default() + } else { + format!("with [{}]", values.iter().join(", ")) + } + + }, + _ => String::default() + }; + + log::debug!( + "{} 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.len() == 0 { + 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))) + } +} diff --git a/src/main.rs b/src/main.rs index bf2ed607..867995a2 100644 --- a/src/main.rs +++ b/src/main.rs @@ -4,6 +4,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, @@ -19,6 +20,7 @@ mod fork; mod formatter; mod hardhat; mod http_fork_source; +mod logging_middleware; mod node; mod resolver; mod system_contracts; @@ -44,7 +46,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}; @@ -100,6 +102,7 @@ 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, @@ -110,7 +113,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()); @@ -335,7 +338,8 @@ async fn main() -> anyhow::Result<()> { let hardhat = HardhatNamespaceImpl::new(node.get_inner()); let threads = build_json_http( - SocketAddr::new(IpAddr::V4(Ipv4Addr::new(0, 0, 0, 0)), opt.port), + SocketAddr::new(IpAddr::V4(Ipv4Addr::new(127, 0, 0, 1)), opt.port), + log_level_filter, node, net, config_api, diff --git a/src/node.rs b/src/node.rs index 187a61a7..ec7af812 100644 --- a/src/node.rs +++ b/src/node.rs @@ -559,7 +559,7 @@ impl InMemoryNodeInner { fn not_implemented( method_name: &str, ) -> jsonrpc_core::BoxFuture> { - log::info!("Method {} is not implemented", method_name); + log::info!("{}", format!("Method {} is not implemented", method_name).yellow()); Err(jsonrpc_core::Error { data: None, code: jsonrpc_core::ErrorCode::MethodNotFound, From aa90f9d1594f818f40e934f9f4f0af04f35220ac Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Fri, 15 Sep 2023 18:08:03 +0100 Subject: [PATCH 2/8] Update yellow log to warning --- src/node.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/node.rs b/src/node.rs index ec7af812..4fde9d94 100644 --- a/src/node.rs +++ b/src/node.rs @@ -559,7 +559,7 @@ impl InMemoryNodeInner { fn not_implemented( method_name: &str, ) -> jsonrpc_core::BoxFuture> { - log::info!("{}", format!("Method {} is not implemented", method_name).yellow()); + log::warn!("Method {} is not implemented", method_name); Err(jsonrpc_core::Error { data: None, code: jsonrpc_core::ErrorCode::MethodNotFound, From 42032947fa5bdfa5f62226edeb2663cd4af21565 Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Fri, 15 Sep 2023 18:18:05 +0100 Subject: [PATCH 3/8] revert unexpected change to ip address of service --- src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/main.rs b/src/main.rs index 867995a2..a8a411e4 100644 --- a/src/main.rs +++ b/src/main.rs @@ -338,7 +338,7 @@ async fn main() -> anyhow::Result<()> { let hardhat = HardhatNamespaceImpl::new(node.get_inner()); let threads = build_json_http( - SocketAddr::new(IpAddr::V4(Ipv4Addr::new(127, 0, 0, 1)), opt.port), + SocketAddr::new(IpAddr::V4(Ipv4Addr::new(0, 0, 0, 0)), opt.port), log_level_filter, node, net, From 667c20e4205ce1db285ae9ab95d6f90daec9ec27 Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Fri, 15 Sep 2023 18:25:45 +0100 Subject: [PATCH 4/8] fix linting --- src/logging_middleware.rs | 53 +++++++++++++++++++++------------------ src/node.rs | 6 ++--- 2 files changed, 31 insertions(+), 28 deletions(-) diff --git a/src/logging_middleware.rs b/src/logging_middleware.rs index 01c8edc4..39717d45 100644 --- a/src/logging_middleware.rs +++ b/src/logging_middleware.rs @@ -1,8 +1,10 @@ use colored::Colorize; -use itertools::Itertools; -use jsonrpc_core::{Middleware, Metadata, Request, Response, middleware, FutureResponse, Call, Params}; use futures::future::Either; use futures::Future; +use itertools::Itertools; +use jsonrpc_core::{ + middleware, Call, FutureResponse, Metadata, Middleware, Params, Request, Response, +}; use log::LevelFilter; #[derive(Clone, Debug, Default)] @@ -23,14 +25,14 @@ impl LoggingMiddleware { /// 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; + 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, - { + fn on_request(&self, request: Request, meta: Meta, next: F) -> Either + where + F: FnOnce(Request, Meta) -> X + Send, + X: Future> + Send + 'static, + { match &request { Request::Single(call) => { match call { @@ -39,29 +41,30 @@ impl Middleware for LoggingMiddleware { LevelFilter::Debug => { let full_params = match &method_call.params { Params::Array(values) => { - if values.len() == 0 { + if values.is_empty() { String::default() } else { format!("with [{}]", values.iter().join(", ")) } - - }, - _ => String::default() + } + _ => String::default(), }; log::debug!( "{} was called {}", method_call.method.cyan(), - full_params); - }, + full_params + ); + } _ => { // Generate truncated params for requests with massive payloads let truncated_params = match &method_call.params { Params::Array(values) => { - if values.len() == 0 { + if values.is_empty() { String::default() } else { - format!("with [{}]", + format!( + "with [{}]", values .iter() .map(|s| { @@ -76,24 +79,24 @@ impl Middleware for LoggingMiddleware { .join(", ") ) } - - }, - _ => String::default() + } + _ => String::default(), }; log::info!( "{} was called {}", method_call.method.cyan(), - truncated_params); + truncated_params + ); } } - }, + } _ => {} } - }, + } _ => {} }; - Either::Left(Box::pin(next(request, meta))) - } + Either::Left(Box::pin(next(request, meta))) + } } diff --git a/src/node.rs b/src/node.rs index 4fde9d94..7890f19b 100644 --- a/src/node.rs +++ b/src/node.rs @@ -1994,7 +1994,7 @@ mod tests { .unwrap(); tx.set_input(vec![], H256::repeat_byte(0x01)); - node.apply_txs(vec![tx.into()]).expect("failed applying tx"); + node.apply_txs(vec![tx]).expect("failed applying tx"); let expected_block_hash = H256::from_str("0x89c0aa770eba1f187235bdad80de9c01fe81bca415d442ca892f087da56fa109") @@ -2120,7 +2120,7 @@ mod tests { .unwrap(); tx.set_input(vec![], H256::repeat_byte(0x01)); - node.apply_txs(vec![tx.into()]).expect("failed applying tx"); + node.apply_txs(vec![tx]).expect("failed applying tx"); let expected_block_number = 1; let actual_block = node @@ -2197,7 +2197,7 @@ mod tests { .unwrap(); tx.set_input(vec![], H256::repeat_byte(0x01)); - node.apply_txs(vec![tx.into()]).expect("failed applying tx"); + node.apply_txs(vec![tx]).expect("failed applying tx"); let latest_block_number = 1; let actual_block = node From 118e92df4065d83ce53f8fa0f1f0fb6ac26f8e6d Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Fri, 15 Sep 2023 18:36:20 +0100 Subject: [PATCH 5/8] fix even more linting --- src/logging_middleware.rs | 100 +++++++++++++++++--------------------- src/main.rs | 1 + 2 files changed, 45 insertions(+), 56 deletions(-) diff --git a/src/logging_middleware.rs b/src/logging_middleware.rs index 39717d45..ceaa726e 100644 --- a/src/logging_middleware.rs +++ b/src/logging_middleware.rs @@ -33,68 +33,56 @@ impl Middleware for LoggingMiddleware { F: FnOnce(Request, Meta) -> X + Send, X: Future> + Send + 'static, { - match &request { - Request::Single(call) => { - match call { - Call::MethodCall(method_call) => { - match self.log_level_filter { - LevelFilter::Debug => { - 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::debug!( - "{} was called {}", - method_call.method.cyan(), - full_params - ); + if let Request::Single(Call::MethodCall(method_call)) = &request { + match self.log_level_filter { + LevelFilter::Debug => { + let full_params = match &method_call.params { + Params::Array(values) => { + if values.is_empty() { + String::default() + } else { + format!("with [{}]", values.iter().join(", ")) } - _ => { - // 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(), - }; + } + _ => String::default(), + }; - log::info!( - "{} was called {}", - method_call.method.cyan(), - truncated_params - ); + log::debug!("{} 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))) diff --git a/src/main.rs b/src/main.rs index a8a411e4..363e8374 100644 --- a/src/main.rs +++ b/src/main.rs @@ -98,6 +98,7 @@ 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, >( From 91d373e5f377a24a433fac34b589a1ac162360c1 Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Mon, 18 Sep 2023 17:05:28 +0100 Subject: [PATCH 6/8] chore: add trace LogLevel. Update incoming request logs with full params to Trace. Fix unit test. --- src/logging_middleware.rs | 4 ++-- src/main.rs | 2 ++ src/node.rs | 26 +------------------------- 3 files changed, 5 insertions(+), 27 deletions(-) diff --git a/src/logging_middleware.rs b/src/logging_middleware.rs index ceaa726e..d99ba059 100644 --- a/src/logging_middleware.rs +++ b/src/logging_middleware.rs @@ -35,7 +35,7 @@ impl Middleware for LoggingMiddleware { { if let Request::Single(Call::MethodCall(method_call)) = &request { match self.log_level_filter { - LevelFilter::Debug => { + LevelFilter::Trace => { let full_params = match &method_call.params { Params::Array(values) => { if values.is_empty() { @@ -47,7 +47,7 @@ impl Middleware for LoggingMiddleware { _ => String::default(), }; - log::debug!("{} was called {}", method_call.method.cyan(), full_params); + log::trace!("{} was called {}", method_call.method.cyan(), full_params); } _ => { // Generate truncated params for requests with massive payloads diff --git a/src/main.rs b/src/main.rs index 6f538247..fd6e2e31 100644 --- a/src/main.rs +++ b/src/main.rs @@ -149,6 +149,7 @@ async fn build_json_http< /// Log filter level for the node. #[derive(Debug, Clone, ValueEnum)] enum LogLevel { + Trace, Debug, Info, Warn, @@ -158,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, diff --git a/src/node.rs b/src/node.rs index 812b0ff6..bae5f483 100644 --- a/src/node.rs +++ b/src/node.rs @@ -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 From 44d541e8ec26bdd3c0415b55ed800c3baa75df84 Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Mon, 18 Sep 2023 17:25:11 +0100 Subject: [PATCH 7/8] chore: add Trace log for API responses --- src/logging_middleware.rs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/logging_middleware.rs b/src/logging_middleware.rs index d99ba059..a33f357b 100644 --- a/src/logging_middleware.rs +++ b/src/logging_middleware.rs @@ -1,5 +1,5 @@ use colored::Colorize; -use futures::future::Either; +use futures::{future::Either, FutureExt}; use futures::Future; use itertools::Itertools; use jsonrpc_core::{ @@ -85,6 +85,9 @@ impl Middleware for LoggingMiddleware { } }; - Either::Left(Box::pin(next(request, meta))) + Either::Left(Box::pin(next(request, meta).map(move |res| { + log::trace!("API response => {:?}", res); + res + }))) } } From 1277eefb09b5229e9327f02dbbfdb6bf0bc201fe Mon Sep 17 00:00:00 2001 From: MexicanAce Date: Mon, 18 Sep 2023 17:33:53 +0100 Subject: [PATCH 8/8] fix lint --- src/hardhat.rs | 6 +++--- src/logging_middleware.rs | 8 ++++---- src/testing.rs | 5 ++--- 3 files changed, 9 insertions(+), 10 deletions(-) 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 index a33f357b..b91f6122 100644 --- a/src/logging_middleware.rs +++ b/src/logging_middleware.rs @@ -1,6 +1,6 @@ use colored::Colorize; -use futures::{future::Either, FutureExt}; use futures::Future; +use futures::{future::Either, FutureExt}; use itertools::Itertools; use jsonrpc_core::{ middleware, Call, FutureResponse, Metadata, Middleware, Params, Request, Response, @@ -86,8 +86,8 @@ impl Middleware for LoggingMiddleware { }; Either::Left(Box::pin(next(request, meta).map(move |res| { - log::trace!("API response => {:?}", res); - res - }))) + log::trace!("API response => {:?}", res); + res + }))) } } 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())