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":"<METHOD>","params":<PARAMS>,"id":<ID>}
DEBUG send: {"jsonrpc":"2.0","result":"<RESULT>","id":<ID>}
```

* style: cargo fmt

* fix: missed logs

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<F
 			// If the channel is closed, then the `Client` has been destroyed and we
 			// stop this task.
 			Either::Left(None) => {
-				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<F
 
 			// User called `notification` on the front-end.
 			Either::Left(Some(FrontToBack::Notification { method, params })) => {
-				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<F
 
 			// Received a response to a request from the server.
 			Either::Right(Ok(RawClientEvent::Response { request_id, result })) => {
-				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));
 			}
 

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?;

src/client/http/transport.rs

@@ -73,6 +73,7 @@ impl HttpTransportClient {
 		&'s mut self,
 		request: jsonrpc::Request,
 	) -> Pin<Box<dyn Future<Output = Result<(), RequestError>> + 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)
 		})
 	}

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()

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) => {

src/client/ws/transport.rs

@@ -198,7 +198,7 @@ impl WsTransportClient {
 		request: jsonrpc::Request,
 	) -> Pin<Box<dyn Future<Output = Result<(), WsConnectError>> + 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)
 		})
 	}

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<RegisteredMethod, Error> {
-		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() {

src/http/transport/background.rs

@@ -125,8 +125,6 @@ async fn process_request(
 	fg_process_tx: &mut mpsc::Sender<Request>,
 	access_control: &AccessControl,
 ) -> hyper::Response<hyper::Body> {
-	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"),
 			}
 		}

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<HttpTransportServer, Box<dyn error::Error + Send + Sync>> {
 		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 }
 		})
 	}
 

src/ws/server.rs

@@ -184,11 +184,11 @@ impl Server {
 		method_name: String,
 		allow_losses: bool,
 	) -> Result<RegisteredNotification, Error> {
-		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<RegisteredMethod, Error> {
-		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<RegisteredSubscription, Error> {
-		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,23 +352,29 @@ 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 {
 				unique_id,
 				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,17 +428,16 @@ 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 => {
 							request.respond(Err(From::from(jsonrpc::ErrorCode::ServerError(0))));
 						}
 					}
 				} 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 {