From 82c3c313cc802086a62697e7d034c5e0c8a8f3b8 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Thu, 26 Sep 2024 22:35:27 +0200 Subject: [PATCH 1/7] Add rpc request-response logging --- Cargo.lock | 2 ++ crates/common/Cargo.toml | 2 ++ crates/common/src/rpc/mod.rs | 37 +++++++++++++++++++++++++++++-- crates/sequencer/src/sequencer.rs | 4 +++- 4 files changed, 42 insertions(+), 3 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 4ac49eafd..b3c2e75a6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1751,6 +1751,7 @@ dependencies = [ "anyhow", "backoff", "citrea-primitives", + "futures", "hyper 1.4.1", "jsonrpsee", "lru", @@ -1758,6 +1759,7 @@ dependencies = [ "sov-rollup-interface", "tokio", "tower-http", + "tracing", ] [[package]] diff --git a/crates/common/Cargo.toml b/crates/common/Cargo.toml index 5cd4df593..0557c63da 100644 --- a/crates/common/Cargo.toml +++ b/crates/common/Cargo.toml @@ -14,11 +14,13 @@ resolver = "2" # 3rd-party deps anyhow = { workspace = true } backoff = { workspace = true } +futures = { workspace = true } hyper = { workspace = true } jsonrpsee = { workspace = true, features = ["http-client", "server"] } lru = { workspace = true } tokio = { workspace = true } tower-http = { workspace = true } +tracing = { workspace = true } # Sov SDK deps sov-db = { path = "../sovereign-sdk/full-node/db/sov-db" } diff --git a/crates/common/src/rpc/mod.rs b/crates/common/src/rpc/mod.rs index 87deada37..01fc283c2 100644 --- a/crates/common/src/rpc/mod.rs +++ b/crates/common/src/rpc/mod.rs @@ -1,12 +1,15 @@ //! Common RPC crate provides helper methods that are needed in rpc servers use std::time::Duration; +use futures::future::BoxFuture; +use futures::FutureExt; use hyper::Method; use jsonrpsee::core::RegisterMethodError; use jsonrpsee::server::middleware::http::ProxyGetRequestLayer; +use jsonrpsee::server::middleware::rpc::RpcServiceT; use jsonrpsee::types::error::{INTERNAL_ERROR_CODE, INTERNAL_ERROR_MSG}; -use jsonrpsee::types::ErrorObjectOwned; -use jsonrpsee::RpcModule; +use jsonrpsee::types::{ErrorObjectOwned, Request}; +use jsonrpsee::{MethodResponse, RpcModule}; use sov_db::ledger_db::{LedgerDB, SharedLedgerOps}; use sov_db::schema::types::BatchNumber; use tower_http::cors::{Any, CorsLayer}; @@ -77,3 +80,33 @@ pub fn get_cors_layer() -> CorsLayer { .allow_origin(Any) .allow_headers(Any) } + +#[derive(Clone)] +pub struct Logger(pub S); + +impl<'a, S> RpcServiceT<'a> for Logger +where + S: RpcServiceT<'a> + Send + Sync + Clone + 'a, +{ + type Future = BoxFuture<'a, MethodResponse>; + + fn call(&self, req: Request<'a>) -> Self::Future { + let req_id = req.id(); + let req_method = req.method_name().to_string(); + + tracing::info!(id = ?req_id, method = ?req_method, params = ?req.params().as_str(), "rpc_request"); + + let service = self.0.clone(); + async move { + let resp = service.call(req).await; + if resp.is_success() { + tracing::info!(id = ?req_id, method = ?req_method, result = ?resp.as_result(), "rpc_success"); + } else { + tracing::warn!(id = ?req_id, method = ?req_method, result = ?resp.as_result(), "rpc_error"); + } + + resp + } + .boxed() + } +} diff --git a/crates/sequencer/src/sequencer.rs b/crates/sequencer/src/sequencer.rs index 110b63d38..b13fdedf8 100644 --- a/crates/sequencer/src/sequencer.rs +++ b/crates/sequencer/src/sequencer.rs @@ -17,7 +17,7 @@ use citrea_stf::runtime::Runtime; use digest::Digest; use futures::channel::mpsc::{unbounded, UnboundedReceiver, UnboundedSender}; use futures::StreamExt; -use jsonrpsee::server::{BatchRequestConfig, ServerBuilder}; +use jsonrpsee::server::{BatchRequestConfig, RpcServiceBuilder, ServerBuilder}; use jsonrpsee::RpcModule; use parking_lot::Mutex; use reth_primitives::{Address, IntoRecoveredTransaction, TxHash}; @@ -212,6 +212,7 @@ where let middleware = tower::ServiceBuilder::new().layer(citrea_common::rpc::get_cors_layer()); // .layer(citrea_common::rpc::get_healthcheck_proxy_layer()); + let rpc_middleware = RpcServiceBuilder::new().layer_fn(citrea_common::rpc::Logger); let _handle = tokio::spawn(async move { let server = ServerBuilder::default() @@ -221,6 +222,7 @@ where .max_response_body_size(max_response_body_size) .set_batch_request_config(BatchRequestConfig::Limit(batch_requests_limit)) .set_http_middleware(middleware) + .set_rpc_middleware(rpc_middleware) .build([listen_address].as_ref()) .await; From 5d5607462f1ff5d0fee252a1e6136286f95d4d37 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Thu, 26 Sep 2024 22:39:54 +0200 Subject: [PATCH 2/7] Remove error logging on sequencer client --- crates/sequencer-client/src/lib.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/crates/sequencer-client/src/lib.rs b/crates/sequencer-client/src/lib.rs index 6413d71c7..f65317647 100644 --- a/crates/sequencer-client/src/lib.rs +++ b/crates/sequencer-client/src/lib.rs @@ -28,7 +28,7 @@ impl SequencerClient { } /// Gets l2 block given l2 height - #[instrument(level = "trace", skip(self), err, ret)] + #[instrument(level = "trace", skip(self), ret)] pub async fn get_soft_confirmation( &self, num: u64, @@ -48,7 +48,7 @@ impl SequencerClient { } /// Gets l2 blocks given a range - #[instrument(level = "trace", skip(self), err, ret)] + #[instrument(level = "trace", skip(self), ret)] pub async fn get_soft_confirmation_range( &self, range: RangeInclusive, @@ -71,7 +71,7 @@ impl SequencerClient { } /// Gets l2 block height - #[instrument(level = "trace", skip(self), err, ret)] + #[instrument(level = "trace", skip(self), ret)] pub async fn block_number(&self) -> Result { self.client .request("ledger_getHeadSoftConfirmationHeight", rpc_params![]) @@ -79,14 +79,14 @@ impl SequencerClient { } /// Sends raw tx to sequencer - #[instrument(level = "trace", skip_all, err, ret)] + #[instrument(level = "trace", skip_all, ret)] pub async fn send_raw_tx(&self, tx: Bytes) -> Result { self.client .request("eth_sendRawTransaction", rpc_params![tx]) .await } - #[instrument(level = "trace", skip(self), err, ret)] + #[instrument(level = "trace", skip(self), ret)] pub async fn get_tx_by_hash( &self, tx_hash: B256, From 820043fff741c5346464f3d80f6399c611d93630 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Fri, 27 Sep 2024 09:52:06 +0200 Subject: [PATCH 3/7] Add rpc logging to fullnode --- crates/fullnode/src/runner.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/crates/fullnode/src/runner.rs b/crates/fullnode/src/runner.rs index 070293616..a04a6d5b3 100644 --- a/crates/fullnode/src/runner.rs +++ b/crates/fullnode/src/runner.rs @@ -9,7 +9,7 @@ use citrea_common::cache::L1BlockCache; use citrea_common::da::get_da_block_at_height; use citrea_primitives::types::SoftConfirmationHash; use jsonrpsee::core::client::Error as JsonrpseeError; -use jsonrpsee::server::{BatchRequestConfig, ServerBuilder}; +use jsonrpsee::server::{BatchRequestConfig, RpcServiceBuilder, ServerBuilder}; use jsonrpsee::RpcModule; use sequencer_client::{GetSoftConfirmationResponse, SequencerClient}; use sov_db::ledger_db::NodeLedgerOps; @@ -176,6 +176,7 @@ where let middleware = tower::ServiceBuilder::new() .layer(citrea_common::rpc::get_cors_layer()) .layer(citrea_common::rpc::get_healthcheck_proxy_layer()); + let rpc_middleware = RpcServiceBuilder::new().layer_fn(citrea_common::rpc::Logger); let _handle = tokio::spawn(async move { let server = ServerBuilder::default() @@ -185,6 +186,7 @@ where .max_response_body_size(max_response_body_size) .set_batch_request_config(BatchRequestConfig::Limit(batch_requests_limit)) .set_http_middleware(middleware) + .set_rpc_middleware(rpc_middleware) .build([listen_address].as_ref()) .await; From 6a0aa722e5c051194966748db5ab8c734483905b Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Fri, 27 Sep 2024 10:34:48 +0200 Subject: [PATCH 4/7] Log to debug --- crates/common/src/rpc/mod.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/common/src/rpc/mod.rs b/crates/common/src/rpc/mod.rs index 01fc283c2..b8a15f454 100644 --- a/crates/common/src/rpc/mod.rs +++ b/crates/common/src/rpc/mod.rs @@ -94,13 +94,13 @@ where let req_id = req.id(); let req_method = req.method_name().to_string(); - tracing::info!(id = ?req_id, method = ?req_method, params = ?req.params().as_str(), "rpc_request"); + tracing::debug!(id = ?req_id, method = ?req_method, params = ?req.params().as_str(), "rpc_request"); let service = self.0.clone(); async move { let resp = service.call(req).await; if resp.is_success() { - tracing::info!(id = ?req_id, method = ?req_method, result = ?resp.as_result(), "rpc_success"); + tracing::debug!(id = ?req_id, method = ?req_method, result = ?resp.as_result(), "rpc_success"); } else { tracing::warn!(id = ?req_id, method = ?req_method, result = ?resp.as_result(), "rpc_error"); } From bc0a6a92976b8ef21655b5bdb4989bad15916270 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Fri, 27 Sep 2024 10:36:15 +0200 Subject: [PATCH 5/7] Add Debug derive to Logger --- crates/common/src/rpc/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/common/src/rpc/mod.rs b/crates/common/src/rpc/mod.rs index b8a15f454..26fed170b 100644 --- a/crates/common/src/rpc/mod.rs +++ b/crates/common/src/rpc/mod.rs @@ -81,7 +81,7 @@ pub fn get_cors_layer() -> CorsLayer { .allow_headers(Any) } -#[derive(Clone)] +#[derive(Debug, Clone)] pub struct Logger(pub S); impl<'a, S> RpcServiceT<'a> for Logger From 99f44df2c919e9624d03b32c7ba05bbf27efa678 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Fri, 27 Sep 2024 10:58:16 +0200 Subject: [PATCH 6/7] Remove info logs in rpc handlers --- crates/ethereum-rpc/src/lib.rs | 29 ----------------------------- 1 file changed, 29 deletions(-) diff --git a/crates/ethereum-rpc/src/lib.rs b/crates/ethereum-rpc/src/lib.rs index 01bdcb209..002126820 100644 --- a/crates/ethereum-rpc/src/lib.rs +++ b/crates/ethereum-rpc/src/lib.rs @@ -28,7 +28,6 @@ use subscription::{handle_logs_subscription, handle_new_heads_subscription}; use tokio::join; use tokio::sync::broadcast; use trace::{debug_trace_by_block_number, handle_debug_trace_chain}; -use tracing::info; #[derive(Clone, Debug, serde::Serialize, serde::Deserialize, PartialEq)] #[serde(rename_all = "camelCase")] @@ -93,13 +92,10 @@ fn register_rpc_methods( enable_subscriptions: bool, ) -> Result<(), jsonrpsee::core::RegisterMethodError> { rpc.register_async_method("web3_clientVersion", |_, ethereum, _| async move { - info!("eth module: web3_clientVersion"); - Ok::<_, ErrorObjectOwned>(ethereum.web3_client_version.clone()) })?; rpc.register_blocking_method("web3_sha3", move |params, _, _| { - info!("eth module: web3_sha3"); let data: Bytes = params.one()?; let hash = B256::from_slice(keccak256(&data).as_slice()); @@ -108,7 +104,6 @@ fn register_rpc_methods( })?; rpc.register_blocking_method("eth_gasPrice", move |_, ethereum, _| { - info!("eth module: eth_gasPrice"); let price = { let mut working_set = WorkingSet::::new(ethereum.storage.clone()); @@ -121,7 +116,6 @@ fn register_rpc_methods( })?; rpc.register_blocking_method("eth_maxFeePerGas", move |_, ethereum, _| { - info!("eth module: eth_maxFeePerGas"); let max_fee_per_gas = { let mut working_set = WorkingSet::::new(ethereum.storage.clone()); @@ -134,7 +128,6 @@ fn register_rpc_methods( })?; rpc.register_blocking_method("eth_maxPriorityFeePerGas", move |_, ethereum, _| { - info!("eth module: eth_maxPriorityFeePerGas"); let max_priority_fee = { let mut working_set = WorkingSet::::new(ethereum.storage.clone()); @@ -147,7 +140,6 @@ fn register_rpc_methods( })?; rpc.register_blocking_method("eth_feeHistory", move |params, ethereum, _| { - info!("eth module: eth_feeHistory"); let mut params = params.sequence(); let block_count: Index = params.next()?; @@ -173,15 +165,11 @@ fn register_rpc_methods( #[cfg(feature = "local")] rpc.register_async_method("eth_accounts", |_, ethereum, _| async move { - info!("eth module: eth_accounts"); - Ok::<_, ErrorObjectOwned>(ethereum.eth_signer.signers()) })?; // #[cfg(feature = "local")] // rpc.register_async_method("eth_sendTransaction", |parameters, ethereum| async move { - // info!("eth module: eth_sendTransaction"); - // let mut transaction_request: TransactionRequest = parameters.one().unwrap(); // let evm = Evm::::default(); @@ -405,8 +393,6 @@ fn register_rpc_methods( rpc.register_blocking_method::, ErrorObjectOwned>, _>( "debug_traceBlockByHash", move |parameters, ethereum, _| { - info!("eth module: debug_traceBlockByHash"); - let mut params = parameters.sequence(); let block_hash: B256 = params.next()?; @@ -429,8 +415,6 @@ fn register_rpc_methods( rpc.register_blocking_method::, ErrorObjectOwned>, _>( "debug_traceBlockByNumber", move |parameters, ethereum, _| { - info!("eth module: debug_traceBlockByNumber"); - let mut params = parameters.sequence(); let block_number: BlockNumberOrTag = params.next()?; @@ -457,8 +441,6 @@ fn register_rpc_methods( // else; calls the debug_trace_transaction_block function in evm // that function traces the entire block, returns all the traces to here // then we put them into cache and return the trace of the requested transaction - info!(params = ?parameters, "eth module: debug_traceTransaction"); - let mut params = parameters.sequence(); let tx_hash: B256 = params.next()?; @@ -493,8 +475,6 @@ fn register_rpc_methods( )?; rpc.register_async_method("txpool_content", |_, _, _| async move { - info!("eth module: txpool_content"); - // This is a simple mock for serde. let json = json!({ "pending": {}, @@ -507,8 +487,6 @@ fn register_rpc_methods( rpc.register_async_method( "eth_getUncleByBlockHashAndIndex", |parameters, _, _| async move { - info!("eth module: eth_getUncleByBlockHashAndIndex"); - let mut params = parameters.sequence(); let _block_hash: String = params.next()?; @@ -524,7 +502,6 @@ fn register_rpc_methods( rpc.register_async_method::, _, _>( "eth_sendRawTransaction", |parameters, ethereum, _| async move { - info!(params = ?parameters, "Full Node: eth_sendRawTransaction"); // send this directly to the sequencer let data: Bytes = parameters.one()?; // sequencer client should send it @@ -551,10 +528,6 @@ fn register_rpc_methods( let mut params = parameters.sequence(); let hash: B256 = params.next()?; let mempool_only: Result, ErrorObjectOwned> = params.optional_next(); - info!( - "Full Node: eth_getTransactionByHash({}, {:?})", - hash, mempool_only - ); // check if mempool_only parameter was given what was its value match mempool_only { @@ -612,8 +585,6 @@ fn register_rpc_methods( rpc.register_async_method::, _, _>( "citrea_syncStatus", |_, ethereum, _| async move { - info!("Full Node: citrea_syncStatus"); - // sequencer client should send latest l2 height // da service should send latest finalized l1 block header let (sequencer_response, da_response) = join!( From 9e01c7f802c1e414f5535d0433acbd221e7f64d1 Mon Sep 17 00:00:00 2001 From: yaziciahmet Date: Fri, 27 Sep 2024 11:23:13 +0200 Subject: [PATCH 7/7] Remove debug logs from evm query --- crates/evm/src/query.rs | 35 ----------------------------------- 1 file changed, 35 deletions(-) diff --git a/crates/evm/src/query.rs b/crates/evm/src/query.rs index fcaff4d25..9adacd625 100644 --- a/crates/evm/src/query.rs +++ b/crates/evm/src/query.rs @@ -30,7 +30,6 @@ use serde::{Deserialize, Serialize}; use sov_modules_api::macros::rpc_gen; use sov_modules_api::prelude::*; use sov_modules_api::WorkingSet; -use tracing::debug; use crate::call::get_cfg_env; use crate::conversions::create_tx_env; @@ -93,8 +92,6 @@ impl Evm { /// Handler for `net_version` #[rpc_method(name = "net_version")] pub fn net_version(&self, working_set: &mut WorkingSet) -> RpcResult { - debug!("evm module: net_version"); - // Network ID is the same as chain ID for most networks let chain_id = self .cfg @@ -108,15 +105,12 @@ impl Evm { /// Handler for: `eth_chainId` #[rpc_method(name = "eth_chainId")] pub fn chain_id(&self, working_set: &mut WorkingSet) -> RpcResult> { - tracing::debug!("evm module: eth_chainId"); - let chain_id = reth_primitives::U64::from( self.cfg .get(working_set) .expect("EVM config must be set at genesis") .chain_id, ); - debug!("evm module: eth_chainId() -> {}", chain_id); Ok(Some(chain_id)) } @@ -129,8 +123,6 @@ impl Evm { details: Option, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getBlockByHash"); - // if block hash is not known, return None let block_number = match self .block_hashes @@ -155,8 +147,6 @@ impl Evm { details: Option, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getBlockByNumber"); - let sealed_block = match self.get_sealed_block_by_number(block_number, working_set)? { Some(sealed_block) => sealed_block, None => return Ok(None), // if block doesn't exist return null @@ -243,8 +233,6 @@ impl Evm { block_number_or_hash: BlockId, working_set: &mut WorkingSet, ) -> RpcResult>> { - debug!("evm module: eth_getBlockReceipts"); - let block = match block_number_or_hash { BlockId::Hash(block_hash) => { let block_number = match self @@ -297,8 +285,6 @@ impl Evm { block_id: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_getBalance"); - self.set_state_to_end_of_evm_block_by_block_id(block_id, working_set)?; // Specs from https://ethereum.org/en/developers/docs/apis/json-rpc @@ -320,7 +306,6 @@ impl Evm { block_id: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_getStorageAt"); // Specs from https://ethereum.org/en/developers/docs/apis/json-rpc self.set_state_to_end_of_evm_block_by_block_id(block_id, working_set)?; @@ -346,8 +331,6 @@ impl Evm { block_id: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_getTransactionCount"); - // Specs from https://ethereum.org/en/developers/docs/apis/json-rpc self.set_state_to_end_of_evm_block_by_block_id(block_id, working_set)?; @@ -368,8 +351,6 @@ impl Evm { block_id: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_getCode"); - self.set_state_to_end_of_evm_block_by_block_id(block_id, working_set)?; let account = self.accounts.get(&address, working_set).unwrap_or_default(); @@ -390,8 +371,6 @@ impl Evm { index: reth_primitives::U64, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getTransactionByBlockHashAndIndex"); - let mut accessory_state = working_set.accessory_state(); let block_number = match self.block_hashes.get(&block_hash, &mut accessory_state) { @@ -440,8 +419,6 @@ impl Evm { index: reth_primitives::U64, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getTransactionByBlockNumberAndIndex"); - let block_number = match self.block_number_for_id(&block_number, working_set) { Ok(block_number) => block_number, Err(EthApiError::UnknownBlockNumber) => return Ok(None), @@ -488,7 +465,6 @@ impl Evm { hash: reth_primitives::B256, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getTransactionReceipt"); let mut accessory_state = working_set.accessory_state(); let tx_number = self.transaction_hashes.get(&hash, &mut accessory_state); @@ -526,7 +502,6 @@ impl Evm { _block_overrides: Option>, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_call"); let mut block_env = match block_id { Some(BlockId::Number(block_num)) => match block_num { BlockNumberOrTag::Pending | BlockNumberOrTag::Latest => BlockEnv::from( @@ -625,8 +600,6 @@ impl Evm { &self, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_blockNumber"); - let block_number = U256::from( self.blocks .len(&mut working_set.accessory_state()) @@ -643,8 +616,6 @@ impl Evm { block_number: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_createAccessList"); - let mut request = request.clone(); let (l1_fee_rate, mut block_env, block_num) = { @@ -805,8 +776,6 @@ impl Evm { block_number: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_estimateGas"); - let estimated = self.estimate_tx_expenses(request, block_number, working_set)?; Ok(estimated.gas_with_l1_overhead()) } @@ -819,7 +788,6 @@ impl Evm { block_number: Option, working_set: &mut WorkingSet, ) -> RpcResult { - debug!("evm module: eth_estimateDiffSize"); if request.gas.is_none() { return Err(EthApiError::InvalidParams("gas must be set".into()))?; } @@ -839,7 +807,6 @@ impl Evm { block_hash: reth_primitives::B256, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getBlockTransactionCountByHash"); // Get the number of transactions in a block given blockhash let block = self.get_block_by_hash(block_hash, None, working_set)?; match block { @@ -855,7 +822,6 @@ impl Evm { block_number: BlockNumberOrTag, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getBlockTransactionCountByNumber"); // Get the number of transactions in a block given block number let block = self.get_block_by_number(Some(block_number), None, working_set)?; match block { @@ -1128,7 +1094,6 @@ impl Evm { hash: reth_primitives::B256, working_set: &mut WorkingSet, ) -> RpcResult> { - debug!("evm module: eth_getTransactionByHash({})", hash); let mut accessory_state = working_set.accessory_state(); let tx_number = self.transaction_hashes.get(&hash, &mut accessory_state);