From 4f8e915d04608e8e827483bc777a5870b1291e9d Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Tue, 13 Feb 2024 09:53:49 +0100 Subject: [PATCH 01/12] Add optional structured logs of RPC related events --- src/config.rs | 36 ++++++++++++++++++++++++++ src/electrum/server.rs | 58 ++++++++++++++++++++++++++++++++++++++++-- 2 files changed, 92 insertions(+), 2 deletions(-) diff --git a/src/config.rs b/src/config.rs index cec2b3f0d..d3529e9e5 100644 --- a/src/config.rs +++ b/src/config.rs @@ -39,6 +39,7 @@ pub struct Config { pub utxos_limit: usize, pub electrum_txs_limit: usize, pub electrum_banner: String, + pub rpc_logging: Option, #[cfg(feature = "liquid")] pub parent_network: BNetwork, @@ -65,6 +66,10 @@ fn str_to_socketaddr(address: &str, what: &str) -> SocketAddr { impl Config { pub fn from_args() -> Config { let network_help = format!("Select network type ({})", Network::names().join(", ")); + let rpc_logging_help = format!( + "Select RPC logging option ({})", + RpcLogging::options().join(", ") + ); let args = App::new("Electrum Rust Server") .version(crate_version!()) @@ -181,6 +186,11 @@ impl Config { .long("electrum-banner") .help("Welcome banner for the Electrum server, shown in the console to clients.") .takes_value(true) + ).arg( + Arg::with_name("rpc_logging") + .long("rpc-logging") + .help(&rpc_logging_help) + .takes_value(true), ); #[cfg(unix)] @@ -381,6 +391,9 @@ impl Config { electrum_rpc_addr, electrum_txs_limit: value_t_or_exit!(m, "electrum_txs_limit", usize), electrum_banner, + rpc_logging: m + .value_of("rpc_logging") + .map(|option| RpcLogging::from(option)), http_addr, http_socket_file, monitoring_addr, @@ -420,6 +433,29 @@ impl Config { } } +#[derive(Debug, Clone)] +pub enum RpcLogging { + Full, + NoParams, +} + +impl RpcLogging { + pub fn options() -> Vec { + return vec!["full".to_string(), "no-params".to_string()]; + } +} + +impl From<&str> for RpcLogging { + fn from(option: &str) -> Self { + match option { + "full" => RpcLogging::Full, + "no-params" => RpcLogging::NoParams, + + _ => panic!("unsupported RPC logging option: {:?}", option), + } + } +} + pub fn get_network_subdir(network: Network) -> Option<&'static str> { match network { #[cfg(not(feature = "liquid"))] diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 939893b75..8bb355aad 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -18,7 +18,7 @@ use bitcoin::consensus::encode::serialize_hex; use elements::encode::serialize_hex; use crate::chain::Txid; -use crate::config::Config; +use crate::config::{Config, RpcLogging}; use crate::electrum::{get_electrum_height, ProtocolVersion}; use crate::errors::*; use crate::metrics::{Gauge, HistogramOpts, HistogramVec, MetricOpts, Metrics}; @@ -101,6 +101,7 @@ struct Connection { txs_limit: usize, #[cfg(feature = "electrum-discovery")] discovery: Option>, + rpc_logging: Option, } impl Connection { @@ -111,6 +112,7 @@ impl Connection { stats: Arc, txs_limit: usize, #[cfg(feature = "electrum-discovery")] discovery: Option>, + rpc_logging: Option, ) -> Connection { Connection { query, @@ -123,6 +125,7 @@ impl Connection { txs_limit, #[cfg(feature = "electrum-discovery")] discovery, + rpc_logging, } } @@ -490,6 +493,27 @@ impl Connection { Ok(result) } + fn log_rpc_event(&self, entries: &Vec<(&str, Value)>) { + if let Some(_) = self.rpc_logging { + let mut log = json!({}); + + if let Some(log_map) = log.as_object_mut() { + entries.into_iter().for_each(|e| { + log_map.insert(e.0.to_string(), e.1.clone()); + }); + log_map.insert( + "source".to_string(), + json!({ + "ip": self.addr.ip().to_string(), + "port": self.addr.port(), + }), + ); + } + + info!("{}", log); + } + } + fn send_values(&mut self, values: &[Value]) -> Result<()> { for value in values { let line = value.to_string() + "\n"; @@ -507,6 +531,7 @@ impl Connection { trace!("RPC {:?}", msg); match msg { Message::Request(line) => { + let method_info: String; let cmd: Value = from_str(&line).chain_err(|| "invalid JSON format")?; let reply = match ( cmd.get("method"), @@ -517,9 +542,30 @@ impl Connection { Some(&Value::String(ref method)), &Value::Array(ref params), Some(ref id), - ) => self.handle_command(method, params, id)?, + ) => { + let mut log_entries = + vec![("event", json!("rpc request")), ("method", json!(method))]; + + if let Some(RpcLogging::Full) = self.rpc_logging { + log_entries.push(("params", json!(params))); + } + + self.log_rpc_event(&log_entries); + method_info = method.clone(); + + self.handle_command(method, params, id)? + } _ => bail!("invalid command: {}", cmd), }; + + let line = reply.to_string() + "\n"; + + self.log_rpc_event(&vec![ + ("event", json!("rpc response")), + ("payload_size", json!(line.as_bytes().len())), + ("method", json!(method_info)), + ]); + self.send_values(&[reply])? } Message::PeriodicUpdate => { @@ -563,6 +609,9 @@ impl Connection { pub fn run(mut self) { self.stats.clients.inc(); + + self.log_rpc_event(&vec![("event", json!("connection established"))]); + let reader = BufReader::new(self.stream.try_clone().expect("failed to clone TcpStream")); let tx = self.chan.sender(); let child = spawn_thread("reader", || Connection::handle_requests(reader, tx)); @@ -579,6 +628,9 @@ impl Connection { .sub(self.status_hashes.len() as i64); debug!("[{}] shutting down connection", self.addr); + + self.log_rpc_event(&vec![("event", json!("connection closed"))]); + let _ = self.stream.shutdown(Shutdown::Both); if let Err(err) = child.join().expect("receiver panicked") { error!("[{}] receiver failed: {}", self.addr, err); @@ -741,6 +793,7 @@ impl RPC { let garbage_sender = garbage_sender.clone(); #[cfg(feature = "electrum-discovery")] let discovery = discovery.clone(); + let rpc_logging = config.rpc_logging.clone(); let spawned = spawn_thread("peer", move || { info!("[{}] connected peer", addr); @@ -752,6 +805,7 @@ impl RPC { txs_limit, #[cfg(feature = "electrum-discovery")] discovery, + rpc_logging, ); senders.lock().unwrap().push(conn.chan.sender()); conn.run(); From bfa5b9f84e8fcbb77da9f7f6d8b3720bfb683250 Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Fri, 16 Feb 2024 15:31:37 +0100 Subject: [PATCH 02/12] Allocating RPC logs entries only if --electrum-rpc-logging is set --- src/config.rs | 10 ++++----- src/electrum/server.rs | 49 ++++++++++++++++++++++++++---------------- 2 files changed, 36 insertions(+), 23 deletions(-) diff --git a/src/config.rs b/src/config.rs index d3529e9e5..8696ecf8f 100644 --- a/src/config.rs +++ b/src/config.rs @@ -39,7 +39,7 @@ pub struct Config { pub utxos_limit: usize, pub electrum_txs_limit: usize, pub electrum_banner: String, - pub rpc_logging: Option, + pub electrum_rpc_logging: Option, #[cfg(feature = "liquid")] pub parent_network: BNetwork, @@ -187,8 +187,8 @@ impl Config { .help("Welcome banner for the Electrum server, shown in the console to clients.") .takes_value(true) ).arg( - Arg::with_name("rpc_logging") - .long("rpc-logging") + Arg::with_name("electrum_rpc_logging") + .long("electrum-rpc-logging") .help(&rpc_logging_help) .takes_value(true), ); @@ -391,8 +391,8 @@ impl Config { electrum_rpc_addr, electrum_txs_limit: value_t_or_exit!(m, "electrum_txs_limit", usize), electrum_banner, - rpc_logging: m - .value_of("rpc_logging") + electrum_rpc_logging: m + .value_of("electrum_rpc_logging") .map(|option| RpcLogging::from(option)), http_addr, http_socket_file, diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 8bb355aad..491f07da3 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -90,6 +90,14 @@ fn get_status_hash(txs: Vec<(Txid, Option)>, query: &Query) -> Option { + if $self.rpc_logging.is_some() { + $self.log_rpc_event(&$event); + } + }; +} + struct Connection { query: Arc, last_header_entry: Option, @@ -543,14 +551,18 @@ impl Connection { &Value::Array(ref params), Some(ref id), ) => { - let mut log_entries = - vec![("event", json!("rpc request")), ("method", json!(method))]; - - if let Some(RpcLogging::Full) = self.rpc_logging { - log_entries.push(("params", json!(params))); - } - - self.log_rpc_event(&log_entries); + conditionally_log_rpc_event!( + self, + if let Some(RpcLogging::Full) = self.rpc_logging { + vec![ + ("event", json!("rpc request")), + ("method", json!(method)), + ("params", json!(params)), + ] + } else { + vec![("event", json!("rpc request")), ("method", json!(method))] + } + ); method_info = method.clone(); self.handle_command(method, params, id)? @@ -560,11 +572,14 @@ impl Connection { let line = reply.to_string() + "\n"; - self.log_rpc_event(&vec![ - ("event", json!("rpc response")), - ("payload_size", json!(line.as_bytes().len())), - ("method", json!(method_info)), - ]); + conditionally_log_rpc_event!( + self, + vec![ + ("event", json!("rpc response")), + ("payload_size", json!(line.as_bytes().len())), + ("method", json!(method_info)), + ] + ); self.send_values(&[reply])? } @@ -609,8 +624,7 @@ impl Connection { pub fn run(mut self) { self.stats.clients.inc(); - - self.log_rpc_event(&vec![("event", json!("connection established"))]); + conditionally_log_rpc_event!(self, vec![("event", json!("connection established"))]); let reader = BufReader::new(self.stream.try_clone().expect("failed to clone TcpStream")); let tx = self.chan.sender(); @@ -628,8 +642,7 @@ impl Connection { .sub(self.status_hashes.len() as i64); debug!("[{}] shutting down connection", self.addr); - - self.log_rpc_event(&vec![("event", json!("connection closed"))]); + conditionally_log_rpc_event!(self, vec![("event", json!("connection closed"))]); let _ = self.stream.shutdown(Shutdown::Both); if let Err(err) = child.join().expect("receiver panicked") { @@ -793,7 +806,7 @@ impl RPC { let garbage_sender = garbage_sender.clone(); #[cfg(feature = "electrum-discovery")] let discovery = discovery.clone(); - let rpc_logging = config.rpc_logging.clone(); + let rpc_logging = config.electrum_rpc_logging.clone(); let spawned = spawn_thread("peer", move || { info!("[{}] connected peer", addr); From 3effb6c2c564c79c935cb1b7fd1a1c74acf07585 Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Fri, 16 Feb 2024 18:18:31 +0100 Subject: [PATCH 03/12] CI fix --- tests/common.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/common.rs b/tests/common.rs index d5bee2074..f8ef0e386 100644 --- a/tests/common.rs +++ b/tests/common.rs @@ -105,6 +105,7 @@ impl TestRunner { utxos_limit: 100, electrum_txs_limit: 100, electrum_banner: "".into(), + electrum_rpc_logging: None, #[cfg(feature = "liquid")] asset_db_path: None, // XXX From e68e454ffeeaef9e0f3227efbb71c48e1363da5f Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Mon, 19 Feb 2024 09:39:07 +0100 Subject: [PATCH 04/12] Fixing review comment --- src/electrum/server.rs | 30 ++++++++++++++---------------- 1 file changed, 14 insertions(+), 16 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 491f07da3..752947e9d 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -502,24 +502,22 @@ impl Connection { } fn log_rpc_event(&self, entries: &Vec<(&str, Value)>) { - if let Some(_) = self.rpc_logging { - let mut log = json!({}); - - if let Some(log_map) = log.as_object_mut() { - entries.into_iter().for_each(|e| { - log_map.insert(e.0.to_string(), e.1.clone()); - }); - log_map.insert( - "source".to_string(), - json!({ - "ip": self.addr.ip().to_string(), - "port": self.addr.port(), - }), - ); - } + let mut log = json!({}); - info!("{}", log); + if let Some(log_map) = log.as_object_mut() { + entries.into_iter().for_each(|e| { + log_map.insert(e.0.to_string(), e.1.clone()); + }); + log_map.insert( + "source".to_string(), + json!({ + "ip": self.addr.ip().to_string(), + "port": self.addr.port(), + }), + ); } + + info!("{}", log); } fn send_values(&mut self, values: &[Value]) -> Result<()> { From dc0f183665a3b57f3fb9c6c8b4283e5d91d5c2df Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Tue, 20 Feb 2024 10:35:28 +0100 Subject: [PATCH 05/12] log_rpc_event refactoring --- src/electrum/server.rs | 72 ++++++++++++++++++++---------------------- 1 file changed, 34 insertions(+), 38 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 752947e9d..e679b7b29 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -93,7 +93,7 @@ fn get_status_hash(txs: Vec<(Txid, Option)>, query: &Query) -> Option { if $self.rpc_logging.is_some() { - $self.log_rpc_event(&$event); + $self.log_rpc_event($event); } }; } @@ -501,23 +501,15 @@ impl Connection { Ok(result) } - fn log_rpc_event(&self, entries: &Vec<(&str, Value)>) { - let mut log = json!({}); - - if let Some(log_map) = log.as_object_mut() { - entries.into_iter().for_each(|e| { - log_map.insert(e.0.to_string(), e.1.clone()); - }); - log_map.insert( - "source".to_string(), - json!({ - "ip": self.addr.ip().to_string(), - "port": self.addr.port(), - }), - ); - } - - info!("{}", log); + fn log_rpc_event(&self, mut log: HashMap<&str, Value>) { + log.insert( + "source".into(), + json!({ + "ip": self.addr.ip().to_string(), + "port": self.addr.port(), + }), + ); + println!("ELECTRUM-RPC-LOGGER: {}", json!(log)); } fn send_values(&mut self, values: &[Value]) -> Result<()> { @@ -549,18 +541,15 @@ impl Connection { &Value::Array(ref params), Some(ref id), ) => { - conditionally_log_rpc_event!( - self, + conditionally_log_rpc_event!(self, { + let mut log: HashMap<&str, Value> = HashMap::new(); + log.insert("event", json!("rpc request")); + log.insert("method", json!(method)); if let Some(RpcLogging::Full) = self.rpc_logging { - vec![ - ("event", json!("rpc request")), - ("method", json!(method)), - ("params", json!(params)), - ] - } else { - vec![("event", json!("rpc request")), ("method", json!(method))] + log.insert("params", json!(params)); } - ); + log + }); method_info = method.clone(); self.handle_command(method, params, id)? @@ -570,14 +559,13 @@ impl Connection { let line = reply.to_string() + "\n"; - conditionally_log_rpc_event!( - self, - vec![ - ("event", json!("rpc response")), - ("payload_size", json!(line.as_bytes().len())), - ("method", json!(method_info)), - ] - ); + conditionally_log_rpc_event!(self, { + let mut log: HashMap<&str, Value> = HashMap::new(); + log.insert("event", json!("rpc response")); + log.insert("method", json!(method_info)); + log.insert("payload_size", json!(line.as_bytes().len())); + log + }); self.send_values(&[reply])? } @@ -622,7 +610,11 @@ impl Connection { pub fn run(mut self) { self.stats.clients.inc(); - conditionally_log_rpc_event!(self, vec![("event", json!("connection established"))]); + conditionally_log_rpc_event!(self, { + let mut log: HashMap<&str, Value> = HashMap::new(); + log.insert("event", json!("connection established")); + log + }); let reader = BufReader::new(self.stream.try_clone().expect("failed to clone TcpStream")); let tx = self.chan.sender(); @@ -640,7 +632,11 @@ impl Connection { .sub(self.status_hashes.len() as i64); debug!("[{}] shutting down connection", self.addr); - conditionally_log_rpc_event!(self, vec![("event", json!("connection closed"))]); + conditionally_log_rpc_event!(self, { + let mut log: HashMap<&str, Value> = HashMap::new(); + log.insert("event", json!("connection closed")); + log + }); let _ = self.stream.shutdown(Shutdown::Both); if let Err(err) = child.join().expect("receiver panicked") { From 6a1abfa1a3529a0132c8e5753a6f1e23177c0bf1 Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Tue, 20 Feb 2024 13:26:28 +0100 Subject: [PATCH 06/12] Refactoring --- src/electrum/server.rs | 61 ++++++++++++++++++++++++------------------ 1 file changed, 35 insertions(+), 26 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index e679b7b29..92aa931e4 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -501,8 +501,8 @@ impl Connection { Ok(result) } - fn log_rpc_event(&self, mut log: HashMap<&str, Value>) { - log.insert( + fn log_rpc_event(&self, mut log: Value) { + log.as_object_mut().unwrap().insert( "source".into(), json!({ "ip": self.addr.ip().to_string(), @@ -541,15 +541,21 @@ impl Connection { &Value::Array(ref params), Some(ref id), ) => { - conditionally_log_rpc_event!(self, { - let mut log: HashMap<&str, Value> = HashMap::new(); - log.insert("event", json!("rpc request")); - log.insert("method", json!(method)); + conditionally_log_rpc_event!( + self, if let Some(RpcLogging::Full) = self.rpc_logging { - log.insert("params", json!(params)); + json!({ + "event": "rpc request", + "method": method, + "params": params + }) + } else { + json!({ + "event": "rpc request", + "method": method + }) } - log - }); + ); method_info = method.clone(); self.handle_command(method, params, id)? @@ -559,13 +565,14 @@ impl Connection { let line = reply.to_string() + "\n"; - conditionally_log_rpc_event!(self, { - let mut log: HashMap<&str, Value> = HashMap::new(); - log.insert("event", json!("rpc response")); - log.insert("method", json!(method_info)); - log.insert("payload_size", json!(line.as_bytes().len())); - log - }); + conditionally_log_rpc_event!( + self, + json!({ + "event": "rpc response", + "method": method_info, + "payload_size": line.as_bytes().len() + }) + ); self.send_values(&[reply])? } @@ -610,11 +617,12 @@ impl Connection { pub fn run(mut self) { self.stats.clients.inc(); - conditionally_log_rpc_event!(self, { - let mut log: HashMap<&str, Value> = HashMap::new(); - log.insert("event", json!("connection established")); - log - }); + conditionally_log_rpc_event!( + self, + json!({ + "event": "connection established" + }) + ); let reader = BufReader::new(self.stream.try_clone().expect("failed to clone TcpStream")); let tx = self.chan.sender(); @@ -632,11 +640,12 @@ impl Connection { .sub(self.status_hashes.len() as i64); debug!("[{}] shutting down connection", self.addr); - conditionally_log_rpc_event!(self, { - let mut log: HashMap<&str, Value> = HashMap::new(); - log.insert("event", json!("connection closed")); - log - }); + conditionally_log_rpc_event!( + self, + json!({ + "event": "connection closed" + }) + ); let _ = self.stream.shutdown(Shutdown::Both); if let Err(err) = child.join().expect("receiver panicked") { From 5b23f0a99f19f02541b198e73eeda5af580d446d Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Tue, 20 Feb 2024 16:35:28 +0100 Subject: [PATCH 07/12] Removing unnecessary json! call --- src/electrum/server.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 92aa931e4..cf430c910 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -509,7 +509,7 @@ impl Connection { "port": self.addr.port(), }), ); - println!("ELECTRUM-RPC-LOGGER: {}", json!(log)); + println!("ELECTRUM-RPC-LOGGER: {}", log); } fn send_values(&mut self, values: &[Value]) -> Result<()> { From 83e904a5f40230a5abc6cdd7b6b910a226a9afda Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Thu, 22 Feb 2024 16:26:15 +0100 Subject: [PATCH 08/12] Adding json id to log --- src/electrum/server.rs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index cf430c910..2ab33c1df 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -547,12 +547,14 @@ impl Connection { json!({ "event": "rpc request", "method": method, - "params": params + "params": params, + "id": id }) } else { json!({ "event": "rpc request", - "method": method + "method": method, + "id": id }) } ); @@ -570,7 +572,8 @@ impl Connection { json!({ "event": "rpc response", "method": method_info, - "payload_size": line.as_bytes().len() + "payload_size": line.as_bytes().len(), + "id": cmd.get("id").unwrap() }) ); From 9dda728fde7e797abf39dde40a83c36c75beb96d Mon Sep 17 00:00:00 2001 From: Nadav Ivgi Date: Thu, 22 Feb 2024 18:11:57 +0000 Subject: [PATCH 09/12] Refactor: handle rpc replies inside the `match` arm This makes `method_into` unnecessary and allows using the `id` variable instead of reading `cmd` again. This also makes it easier to log time durations (added in a followup commit). --- src/electrum/server.rs | 38 ++++++++++++++++++-------------------- 1 file changed, 18 insertions(+), 20 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 2ab33c1df..8b1ec6c30 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -529,9 +529,8 @@ impl Connection { trace!("RPC {:?}", msg); match msg { Message::Request(line) => { - let method_info: String; let cmd: Value = from_str(&line).chain_err(|| "invalid JSON format")?; - let reply = match ( + match ( cmd.get("method"), cmd.get("params").unwrap_or_else(|| &empty_params), cmd.get("id"), @@ -558,26 +557,25 @@ impl Connection { }) } ); - method_info = method.clone(); - self.handle_command(method, params, id)? + let reply = self.handle_command(method, params, id)?; + + conditionally_log_rpc_event!( + self, + json!({ + "event": "rpc response", + "method": method, + "payload_size": reply.to_string().as_bytes().len(), + "id": id, + }) + ); + + self.send_values(&[reply])? + } + _ => { + bail!("invalid command: {}", cmd) } - _ => bail!("invalid command: {}", cmd), - }; - - let line = reply.to_string() + "\n"; - - conditionally_log_rpc_event!( - self, - json!({ - "event": "rpc response", - "method": method_info, - "payload_size": line.as_bytes().len(), - "id": cmd.get("id").unwrap() - }) - ); - - self.send_values(&[reply])? + } } Message::PeriodicUpdate => { let values = self From e7abc4dd6844d1a5cb78304f0edeaf5a1eb941f4 Mon Sep 17 00:00:00 2001 From: Nadav Ivgi Date: Thu, 22 Feb 2024 18:19:52 +0000 Subject: [PATCH 10/12] Some minor formatting and refactoring changes --- src/electrum/server.rs | 38 ++++++++++++-------------------------- 1 file changed, 12 insertions(+), 26 deletions(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 8b1ec6c30..c96e5a396 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -542,20 +542,16 @@ impl Connection { ) => { conditionally_log_rpc_event!( self, - if let Some(RpcLogging::Full) = self.rpc_logging { - json!({ - "event": "rpc request", - "method": method, - "params": params, - "id": id - }) - } else { - json!({ - "event": "rpc request", - "method": method, - "id": id - }) - } + json!({ + "event": "rpc request", + "id": id, + "method": method, + "params": if let Some(RpcLogging::Full) = self.rpc_logging { + json!(params) + } else { + Value::Null + } + }) ); let reply = self.handle_command(method, params, id)?; @@ -618,12 +614,7 @@ impl Connection { pub fn run(mut self) { self.stats.clients.inc(); - conditionally_log_rpc_event!( - self, - json!({ - "event": "connection established" - }) - ); + conditionally_log_rpc_event!(self, json!({ "event": "connection established" })); let reader = BufReader::new(self.stream.try_clone().expect("failed to clone TcpStream")); let tx = self.chan.sender(); @@ -641,12 +632,7 @@ impl Connection { .sub(self.status_hashes.len() as i64); debug!("[{}] shutting down connection", self.addr); - conditionally_log_rpc_event!( - self, - json!({ - "event": "connection closed" - }) - ); + conditionally_log_rpc_event!(self, json!({ "event": "connection closed" })); let _ = self.stream.shutdown(Shutdown::Both); if let Err(err) = child.join().expect("receiver panicked") { From bc08fde612340e6781a86426382a193f353a49e9 Mon Sep 17 00:00:00 2001 From: Nadav Ivgi Date: Thu, 22 Feb 2024 18:26:42 +0000 Subject: [PATCH 11/12] Log the time duration for processing RPC requests --- src/electrum/server.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index c96e5a396..41234475e 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -4,6 +4,7 @@ use std::net::{Shutdown, SocketAddr, TcpListener, TcpStream}; use std::sync::mpsc::{Sender, SyncSender, TrySendError}; use std::sync::{Arc, Mutex}; use std::thread; +use std::time::Instant; use bitcoin::hashes::sha256d::Hash as Sha256dHash; use crypto::digest::Digest; @@ -554,6 +555,7 @@ impl Connection { }) ); + let start_time = Instant::now(); let reply = self.handle_command(method, params, id)?; conditionally_log_rpc_event!( @@ -562,6 +564,7 @@ impl Connection { "event": "rpc response", "method": method, "payload_size": reply.to_string().as_bytes().len(), + "duration_ms": start_time.elapsed().as_millis(), "id": id, }) ); From 96214a870573f1b17cb75865091db924ef6ea5ce Mon Sep 17 00:00:00 2001 From: rem1-dev <150667999+rem1-dev@users.noreply.github.com> Date: Fri, 23 Feb 2024 11:43:35 +0100 Subject: [PATCH 12/12] Change time duration for processing RPC requests log to microseconds --- src/electrum/server.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 41234475e..b319f95eb 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -564,7 +564,7 @@ impl Connection { "event": "rpc response", "method": method, "payload_size": reply.to_string().as_bytes().len(), - "duration_ms": start_time.elapsed().as_millis(), + "duration_µs": start_time.elapsed().as_micros(), "id": id, }) );