From fa0a6ef6e9c1a08f1dc2ff6227dddd0ac0199aac Mon Sep 17 00:00:00 2001 From: Niklas Adolfsson Date: Wed, 4 Nov 2020 09:35:24 +0100 Subject: [PATCH] chore: make `debug log` less verbose. (#153) * chore: make `debug log` less verbose. The debug logging was just too verbose and this commit simplies it as follows: ``` DEBUG recv: {"jsonrpc":"2.0","method":"","params":,"id":} DEBUG send: {"jsonrpc":"2.0","result":"","id":} ``` * style: cargo fmt * fix: missed logs --- src/client/http/client.rs | 15 ++++++------ src/client/http/raw.rs | 1 - src/client/http/transport.rs | 2 ++ src/client/ws/client.rs | 5 ++-- src/client/ws/raw.rs | 1 - src/client/ws/transport.rs | 4 ++-- src/http/server.rs | 15 ++++++++---- src/http/transport/background.rs | 10 ++++---- src/http/transport/mod.rs | 9 +------- src/ws/server.rs | 39 ++++++++++++++++++-------------- src/ws/transport.rs | 24 +++++++++++--------- 11 files changed, 66 insertions(+), 59 deletions(-) diff --git a/src/client/http/client.rs b/src/client/http/client.rs index 4976cafa3f..255ed92eb3 100644 --- a/src/client/http/client.rs +++ b/src/client/http/client.rs @@ -59,7 +59,7 @@ impl Client { ) -> Result<(), Error> { let method = method.into(); let params = params.into(); - log::debug!("[frontend]: client send notification: method={:?}, params={:?}", method, params); + log::trace!("[frontend]: client send notification: method={:?}, params={:?}", method, params); self.backend.clone().send(FrontToBack::Notification { method, params }).await.map_err(Error::InternalChannel) } @@ -74,7 +74,7 @@ impl Client { { let method = method.into(); let params = params.into(); - log::debug!("[frontend]: send request: method={:?}, params={:?}", method, params); + log::trace!("[frontend]: send request: method={:?}, params={:?}", method, params); let (send_back_tx, send_back_rx) = oneshot::channel(); // TODO: send a `ChannelClosed` message if we close the channel unexpectedly @@ -115,7 +115,7 @@ async fn background_task(mut client: RawClient, mut from_front: mpsc::Receiver { - log::trace!("[backend]: client terminated"); + log::trace!("[backend]: background task terminated"); if !ongoing_requests.is_empty() { log::warn!("client was dropped with {} pending requests", ongoing_requests.len()); } @@ -124,16 +124,15 @@ async fn background_task(mut client: RawClient, mut from_front: mpsc::Receiver { - log::trace!("[backend]: client send notification"); + log::trace!("[backend]: send notification"); let _ = client.send_notification(method, params).await; } // User called `request` on the front-end. Either::Left(Some(FrontToBack::StartRequest { method, params, send_back })) => { - log::trace!("[backend]: client prepare to send request={:?}", method); - match client.start_request(method, params).await { + match client.start_request(&method, params).await { Ok(id) => { - log::debug!(target: "jsonrpsee-http-client", "background thread; inserting ingoing request={:?}", id); + log::trace!("[backend]; send request: {:?} id: {:?}", method, id); ongoing_requests.insert(id, send_back); } Err(err) => { @@ -144,7 +143,7 @@ async fn background_task(mut client: RawClient, mut from_front: mpsc::Receiver { - log::trace!("[backend] client received response to req={:?}, result={:?}", request_id, result); + log::trace!("[backend] received response to req={:?}, result={:?}", request_id, result); let _ = ongoing_requests.remove(&request_id).unwrap().send(result.map_err(Error::Request)); } diff --git a/src/client/http/raw.rs b/src/client/http/raw.rs index bda91b818f..e2086f2449 100644 --- a/src/client/http/raw.rs +++ b/src/client/http/raw.rs @@ -189,7 +189,6 @@ impl RawClient { id: jsonrpc::Id::Num(id.0), })); - log::debug!(target: "jsonrpsee-http-raw-client", "request={:?}", request); // Note that in case of an error, we "lose" the request id (as in, it will never be // used). This isn't a problem, however. self.inner.send_request(request).await?; diff --git a/src/client/http/transport.rs b/src/client/http/transport.rs index 5418b34343..5709cc7e21 100644 --- a/src/client/http/transport.rs +++ b/src/client/http/transport.rs @@ -73,6 +73,7 @@ impl HttpTransportClient { &'s mut self, request: jsonrpc::Request, ) -> Pin> + Send + 's>> { + log::debug!("send: {}", jsonrpc::to_string(&request).expect("request valid JSON; qed")); let mut requests_tx = self.requests_tx.clone(); let request = jsonrpc::to_vec(&request).map(|body| { @@ -131,6 +132,7 @@ impl HttpTransportClient { // TODO: use Response::from_json let as_json: jsonrpc::Response = jsonrpc::from_slice(&body).map_err(RequestError::ParseError)?; + log::debug!("recv: {}", jsonrpc::to_string(&as_json).expect("request valid JSON; qed")); Ok(as_json) }) } diff --git a/src/client/ws/client.rs b/src/client/ws/client.rs index 6f3b30ad7f..6200b7f5b6 100644 --- a/src/client/ws/client.rs +++ b/src/client/ws/client.rs @@ -122,7 +122,7 @@ impl Client { ) -> Result<(), Error> { let method = method.into(); let params = params.into(); - log::debug!("[frontend]: client send notification: method={:?}, params={:?}", method, params); + log::trace!("[frontend]: send notification: method={:?}, params={:?}", method, params); self.to_back.clone().send(FrontToBack::Notification { method, params }).await.map_err(Error::InternalChannel) } @@ -137,7 +137,7 @@ impl Client { { let method = method.into(); let params = params.into(); - log::debug!("[frontend]: send request: method={:?}, params={:?}", method, params); + log::trace!("[frontend]: send request: method={:?}, params={:?}", method, params); let (send_back_tx, send_back_rx) = oneshot::channel(); self.to_back.clone().send(FrontToBack::StartRequest { method, params, send_back: send_back_tx }).await?; @@ -171,6 +171,7 @@ impl Client { return Err(Error::Subscription(subscribe_method, unsubscribe_method)); } + log::trace!("[frontend]: subscribe: {:?}, unsubscribe: {:?}", subscribe_method, unsubscribe_method); let (send_back_tx, send_back_rx) = oneshot::channel(); self.to_back .clone() diff --git a/src/client/ws/raw.rs b/src/client/ws/raw.rs index a9df7ffa78..6cc9df54dc 100644 --- a/src/client/ws/raw.rs +++ b/src/client/ws/raw.rs @@ -444,7 +444,6 @@ impl RawClient { /// Processes the response obtained from the server. Updates the internal state of `self` to /// account for it. fn process_response(&mut self, response: jsonrpc::Output) -> Result<(), RawClientError> { - log::debug!(target: "ws-client-raw", "received response: {:?}", response); let request_id = match response.id() { jsonrpc::Id::Num(n) => RawClientRequestId(*n), jsonrpc::Id::Str(s) => { diff --git a/src/client/ws/transport.rs b/src/client/ws/transport.rs index 14a47ea8c4..27ab543327 100644 --- a/src/client/ws/transport.rs +++ b/src/client/ws/transport.rs @@ -198,7 +198,7 @@ impl WsTransportClient { request: jsonrpc::Request, ) -> Pin> + Send + 'a>> { Box::pin(async move { - log::debug!("send request: {:?}", request); + log::debug!("send: {}", jsonrpc::to_string(&request).expect("valid Request; qed")); let request = jsonrpc::to_vec(&request).map_err(WsConnectError::Serialization)?; self.sender.send_binary(request).await?; self.sender.flush().await?; @@ -214,7 +214,7 @@ impl WsTransportClient { let mut message = Vec::new(); self.receiver.receive_data(&mut message).await?; let response = jsonrpc::from_slice(&message).map_err(WsConnectError::ParseError)?; - log::debug!("received response: {:?}", response); + log::debug!("recv: {}", jsonrpc::to_string(&response).expect("valid Request; qed")); Ok(response) }) } diff --git a/src/http/server.rs b/src/http/server.rs index 07da4315ff..f58e0f7829 100644 --- a/src/http/server.rs +++ b/src/http/server.rs @@ -158,6 +158,7 @@ impl Server { return Err(Error::AlreadyRegistered(method_name)); } + log::trace!("[frontend]: register_notification={}", method_name); let (tx, rx) = mpsc::channel(32); self.to_back @@ -178,11 +179,11 @@ impl Server { /// /// Returns an error if the method name was already registered. pub fn register_method(&self, method_name: String) -> Result { - log::debug!("[frontend]: register_method={}", method_name); if !self.registered_methods.lock().insert(method_name.clone()) { return Err(Error::AlreadyRegistered(method_name)); } + log::trace!("[frontend]: register_method={}", method_name); let (tx, rx) = mpsc::channel(32); self.to_back @@ -257,18 +258,24 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR }; match outcome { - Either::Left(None) => return, + Either::Left(None) => { + log::trace!("[backend]: background_task terminated"); + return; + } Either::Left(Some(FrontToBack::AnswerRequest { request_id, answer })) => { + log::trace!("[backend]: answer_request: {:?} id: {:?}", answer, request_id); server.request_by_id(&request_id).unwrap().respond(answer); } Either::Left(Some(FrontToBack::RegisterNotifications { name, handler, allow_losses })) => { + log::trace!("[backend]: register_notification: {:?}", name); registered_notifications.insert(name, (handler, allow_losses)); } Either::Left(Some(FrontToBack::RegisterMethod { name, handler })) => { + log::trace!("[backend]: register_method: {:?}", name); registered_methods.insert(name, handler); } Either::Right(RawServerEvent::Notification(notification)) => { - log::debug!("server received notification: {:?}", notification); + log::trace!("[backend]: received notification: {:?}", notification); if let Some((handler, allow_losses)) = registered_notifications.get_mut(notification.method()) { let params: &jsonrpc::Params = notification.params().into(); // Note: we just ignore errors. It doesn't make sense logically speaking to @@ -281,7 +288,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR } } Either::Right(RawServerEvent::Request(request)) => { - log::debug!("server received request: {:?}", request); + log::trace!("[backend]: received request: {:?}", request); if let Some(handler) = registered_methods.get_mut(request.method()) { let params: &jsonrpc::Params = request.params().into(); match handler.send((request.id(), params.clone())).now_or_never() { diff --git a/src/http/transport/background.rs b/src/http/transport/background.rs index 1c9c4ea849..c47c2d16f3 100644 --- a/src/http/transport/background.rs +++ b/src/http/transport/background.rs @@ -125,8 +125,6 @@ async fn process_request( fg_process_tx: &mut mpsc::Sender, access_control: &AccessControl, ) -> hyper::Response { - log::debug!(target: "jsonrpc-http-transport-server", "Recevied request={:?}", request); - // Process access control if access_control.deny_host(&request) { return response::host_not_allowed(); @@ -164,15 +162,17 @@ async fn process_request( }, }; - log::debug!(target: "http-server transport", "received request={:?}", json_body); - let (tx, rx) = oneshot::channel(); + log::debug!("recv: {}", jsonrpc::to_string(&json_body).unwrap()); let user_facing_rq = Request { send_back: tx, request: json_body }; if fg_process_tx.send(user_facing_rq).await.is_err() { return response::internal_error("JSON requests processing channel has shut down"); } match rx.await { - Ok(response) => response, + Ok(response) => { + log::debug!("send: {:?}", response.body()); + response + } Err(_) => return response::internal_error("JSON request send back channel has shut down"), } } diff --git a/src/http/transport/mod.rs b/src/http/transport/mod.rs index b450e864f0..8b630a23c6 100644 --- a/src/http/transport/mod.rs +++ b/src/http/transport/mod.rs @@ -85,9 +85,6 @@ impl HttpTransportServer { // > might switch out to a different library later without breaking the API. pub async fn new(addr: &SocketAddr) -> Result> { let (background_thread, local_addr) = background::BackgroundHttp::bind(addr).await?; - - log::debug!(target: "jsonrpc-http-server", "Starting jsonrpc http server at address={:?}, local_addr={:?}", addr, local_addr); - Ok(HttpTransportServer { background_thread, local_addr, requests: Default::default(), next_request_id: 0 }) } @@ -118,7 +115,6 @@ impl HttpTransportServer { let request = match self.background_thread.next().await { Ok(r) => r, Err(_) => loop { - log::debug!("http transport server inf loop?!"); futures::pending!() }, }; @@ -144,10 +140,7 @@ impl HttpTransportServer { self.requests.shrink_to_fit(); } - let request = TransportServerEvent::Request { id: request_id, request: request.request }; - - log::debug!(target: "jsonrpc-http-transport-server", "received request: {:?}", request); - request + TransportServerEvent::Request { id: request_id, request: request.request } }) } diff --git a/src/ws/server.rs b/src/ws/server.rs index 7f3a34d921..e53525713c 100644 --- a/src/ws/server.rs +++ b/src/ws/server.rs @@ -184,11 +184,11 @@ impl Server { method_name: String, allow_losses: bool, ) -> Result { - log::debug!("[frontend]: register_notification={}", method_name); if !self.registered_methods.lock().insert(method_name.clone()) { return Err(Error::AlreadyRegistered(method_name)); } + log::trace!("[frontend]: register_notification={}", method_name); let (tx, rx) = mpsc::channel(32); self.to_back @@ -209,11 +209,11 @@ impl Server { /// /// Returns an error if the method name was already registered. pub fn register_method(&self, method_name: String) -> Result { - log::debug!("[frontend]: register_method={}", method_name); if !self.registered_methods.lock().insert(method_name.clone()) { return Err(Error::AlreadyRegistered(method_name)); } + log::trace!("[frontend]: register_method={}", method_name); let (tx, rx) = mpsc::channel(32); self.to_back @@ -234,11 +234,6 @@ impl Server { subscribe_method_name: String, unsubscribe_method_name: String, ) -> Result { - log::debug!( - "[frontend]: server register subscription: subscribe_method={}, unsubscribe_method={}", - subscribe_method_name, - unsubscribe_method_name - ); { let mut registered_methods = self.registered_methods.lock(); @@ -254,6 +249,11 @@ impl Server { } } + log::trace!( + "[frontend]: server register subscription: subscribe_method={}, unsubscribe_method={}", + subscribe_method_name, + unsubscribe_method_name + ); let unique_id = self.next_subscription_unique_id.fetch_add(1, atomic::Ordering::Relaxed); self.to_back @@ -352,14 +352,20 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR }; match outcome { - Either::Left(None) => return, + Either::Left(None) => { + log::trace!("[backend]: background_task terminated"); + return; + } Either::Left(Some(FrontToBack::AnswerRequest { request_id, answer })) => { + log::trace!("[backend]: answer_request: {:?} id: {:?}", answer, request_id); server.request_by_id(&request_id).unwrap().respond(answer); } Either::Left(Some(FrontToBack::RegisterNotifications { name, handler, allow_losses })) => { + log::trace!("[backend]: register_notification: {:?}", name); registered_notifications.insert(name, (handler, allow_losses)); } Either::Left(Some(FrontToBack::RegisterMethod { name, handler })) => { + log::trace!("[backend]: register_method: {:?}", name); registered_methods.insert(name, handler); } Either::Left(Some(FrontToBack::RegisterSubscription { @@ -367,8 +373,8 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR subscribe_method, unsubscribe_method, })) => { - log::debug!( - "[backend]: server register subscription=id={:?}, subscribe_method:{}, unsubscribe_method={}", + log::trace!( + "[backend]: register subscription=id={:?}, subscribe_method:{}, unsubscribe_method={}", unique_id, subscribe_method, unsubscribe_method @@ -388,7 +394,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR subscribed_clients.insert(unique_id, Vec::new()); } Either::Left(Some(FrontToBack::SendOutNotif { unique_id, notification })) => { - log::debug!("[backend]: server preparing response to subscription={:?}", unique_id); + log::trace!("[backend]: preparing response to subscription={:?}", unique_id); debug_assert!(subscribed_clients.contains_key(&unique_id)); if let Some(clients) = subscribed_clients.get(&unique_id) { log::trace!( @@ -408,7 +414,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR } } Either::Right(RawServerEvent::Notification(notification)) => { - log::debug!("[backend]: server received notification: {:?}", notification); + log::debug!("[backend]: received notification: {:?}", notification); if let Some((handler, allow_losses)) = registered_notifications.get_mut(notification.method()) { let params: &jsonrpc::Params = notification.params().into(); // Note: we just ignore errors. It doesn't make sense logically speaking to @@ -422,9 +428,8 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR } Either::Right(RawServerEvent::Request(request)) => { if let Some(handler) = registered_methods.get_mut(request.method()) { - log::debug!("[backend]: server received request: {:?}", request); + log::trace!("[backend]: received request: {:?}", request); let params: &jsonrpc::Params = request.params().into(); - log::debug!("server called handler"); match handler.send((request.id(), params.clone())).now_or_never() { Some(Ok(())) => {} Some(Err(_)) | None => { @@ -432,7 +437,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR } } } else if let Some(sub_unique_id) = subscribe_methods.get(request.method()) { - log::debug!("[backend]: server received subscription: {:?}", request); + log::trace!("[backend]: received subscription: {:?}", request); if let Ok(sub_id) = request.into_subscription() { debug_assert!(subscribed_clients.contains_key(&sub_unique_id)); if let Some(clients) = subscribed_clients.get_mut(&sub_unique_id) { @@ -444,7 +449,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR active_subscriptions.insert(sub_id, *sub_unique_id); } } else if let Some(sub_unique_id) = unsubscribe_methods.get(request.method()) { - log::debug!("[backend]: server received unsubscription: {:?}", request); + log::trace!("[backend]: received unsubscription: {:?}", request); match RawServerSubscriptionId::try_from(request.params()) { Ok(sub_id) => { debug_assert!(subscribed_clients.contains_key(&sub_unique_id)); @@ -473,7 +478,7 @@ async fn background_task(mut server: RawServer, mut from_front: mpsc::UnboundedR // We don't really care whether subscriptions are now ready. } Either::Right(RawServerEvent::SubscriptionsClosed(subscriptions)) => { - log::debug!("[backend]: server close subscriptions: {:?}", subscriptions); + log::trace!("[backend]: close subscriptions: {:?}", subscriptions); // Remove all the subscriptions from `active_subscriptions` and // `subscribed_clients`. for sub_id in subscriptions { diff --git a/src/ws/transport.rs b/src/ws/transport.rs index e205718a8c..f48c2c04bd 100644 --- a/src/ws/transport.rs +++ b/src/ws/transport.rs @@ -182,13 +182,13 @@ impl WsTransportServer { match next { Event::NewConnection(connec) => { - log::debug!("new connection with id: {:?}", self.next_request_id); + log::trace!("{:?}: new connection", self.next_request_id); self.connections_tasks.push( per_connection_task(connec, self.next_request_id.clone(), self.to_front.clone()).boxed(), ); } Event::Event(BackToFront::NewRequest { id, body, sender }) => { - log::debug!("new request with id: {:?}", id); + log::trace!("{:?}: new request", self.next_request_id); let _was_in = self.to_connections.insert(id.clone(), sender); debug_assert!(_was_in.is_none()); return TransportServerEvent::Request { id, request: body }; @@ -206,7 +206,7 @@ impl WsTransportServer { // // The `ws::raw::tests::request_work` is emperic proof of it. if was_in.is_some() { - log::debug!("closed connection with id: {:?}", rq_id); + log::trace!("{:?}: closed connection", self.next_request_id); self.pending_events.push(TransportServerEvent::Closed(rq_id)); } } @@ -370,15 +370,15 @@ async fn per_connection_task( future::Either::Left((socket_packet, _)) => { let socket_packet = match socket_packet { Some(Ok(pq)) => { - log::debug!("received data from WebSocket: {:?}", pq); + log::trace!("{:?}: received data from WebSocket: {:?}", next_request_id, pq); pq } Some(Err(err)) => { - log::error!("failed to receive data from WebSocket: {:?}", err); + log::error!("{:?}: failed to receive data from WebSocket: {:?}", next_request_id, err); return pending_requests; } None => { - log::error!("failed to receive data from Websocket channel closed"); + log::error!("{:?}: failed to receive data from Websocket channel closed", next_request_id); return pending_requests; } }; @@ -399,7 +399,8 @@ async fn per_connection_task( // deserialization failed and the client is not alive Err(e) => { log::warn!( - "Failed to send: {:?} over WebSocket transport with error: {:?}", + "{:?}: Failed to send: {:?} over WebSocket transport with error: {:?}", + next_request_id, response, e ); @@ -411,6 +412,7 @@ async fn per_connection_task( let request_id = WsRequestId(next_request_id.fetch_add(1, atomic::Ordering::Relaxed)); debug_assert_ne!(request_id.0, u64::max_value()); + log::debug!("recv: {}", jsonrpc::to_string(&body).expect("valid Request; qed")); // Important note: since the background task sends messages to the front task via // a channel, and the front task sends messages to the background task via a @@ -432,7 +434,7 @@ async fn per_connection_task( // The channel is down or full. Some(Err(e)) => { log::error!( - "send request={:?} to frontend failed because of {:?}, terminating the connection", + "{:?}: send request to frontend failed because of {:?}, terminating the connection", request_id, e, ); @@ -442,7 +444,7 @@ async fn per_connection_task( // TODO(niklasad1): verify if this is possible to happen "in practice". None => { log::error!( - "send request={:?} to frontend failed future not ready, terminating the connection", + "{:?}: send request to frontend failed future not ready, terminating the connection", request_id, ); return pending_requests; @@ -452,14 +454,14 @@ async fn per_connection_task( // Received data to send on the connection. future::Either::Right((Some(FrontToBack::Send(to_send)), _)) => { - log::trace!("transmit: {:?}", to_send); + log::debug!("send: {}", to_send); if let Err(err) = sender.send_text(&to_send).await { log::warn!("failed to send: {:?} over WebSocket transport with error: {:?}", to_send, err); return pending_requests; } } - // Received data to send on the connection. + // Request finished. future::Either::Right((Some(FrontToBack::Finished(rq_id)), _)) => { log::trace!("finished request_id={:?}", rq_id); let pos = pending_requests.iter().position(|r| *r == rq_id).unwrap();