Uniform log messages (#855)

* client: Log when frontend is dropped

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* client: Never fail to handle frontend messages

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* client: Format frontend warnings

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* client: Format backend messages

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* client: Uniform log messages

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* server: Uniform logs

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* server: Adjust logs

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* test: Fix cargo clippy

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* server: Log error as unrecoverable

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

* Update core/src/client/async_client/mod.rs

Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>

* Update core/src/client/async_client/mod.rs

Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>
Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>

client/transport/src/ws/mod.rs

@@ -199,7 +199,7 @@ impl TransportSenderT for Sender {
 	/// Sends out a ping request. Returns a `Future` that finishes when the request has been
 	/// successfully sent.
 	async fn send_ping(&mut self) -> Result<(), Self::Error> {
-		tracing::debug!("send ping");
+		tracing::debug!("Send ping");
 		// Submit empty slice as "optional" parameter.
 		let slice: &[u8] = &[];
 		// Byte slice fails if the provided slice is larger than 125 bytes.

core/src/client/async_client/helpers.rs

@@ -84,7 +84,7 @@ pub(crate) fn process_subscription_response(
 	let request_id = match manager.get_request_id_by_subscription_id(&sub_id) {
 		Some(request_id) => request_id,
 		None => {
-			tracing::warn!("Subscription ID: {:?} is not an active subscription", sub_id);
+			tracing::warn!("Subscription {:?} is not active", sub_id);
 			return Err(None);
 		}
 	};
@@ -100,7 +100,7 @@ pub(crate) fn process_subscription_response(
 			}
 		},
 		None => {
-			tracing::warn!("Subscription ID: {:?} is not an active subscription", sub_id);
+			tracing::warn!("Subscription {:?} is not active", sub_id);
 			Err(None)
 		}
 	}
@@ -118,7 +118,7 @@ pub(crate) fn process_subscription_close_response(
 	let request_id = match manager.get_request_id_by_subscription_id(&sub_id) {
 		Some(request_id) => request_id,
 		None => {
-			tracing::error!("The server tried to close down an invalid subscription: {:?}", sub_id);
+			tracing::error!("The server tried to close an invalid subscription: {:?}", sub_id);
 			return Err(Error::InvalidSubscriptionId);
 		}
 	};

core/src/client/async_client/manager.rs

@@ -86,9 +86,9 @@ pub(crate) struct RequestManager {
 	/// Reverse lookup, to find a request ID in constant time by `subscription ID` instead of looking through all
 	/// requests.
 	subscriptions: HashMap<SubscriptionId<'static>, RequestId>,
-	/// Pending batch requests
+	/// Pending batch requests.
 	batches: FxHashMap<Vec<RequestId>, BatchState>,
-	/// Registered Methods for incoming notifications
+	/// Registered Methods for incoming notifications.
 	notification_handlers: HashMap<String, SubscriptionSink>,
 }
 
@@ -98,7 +98,7 @@ impl RequestManager {
 		Self::default()
 	}
 
-	/// Tries to insert a new pending call.
+	/// Tries to insert a new pending request.
 	///
 	/// Returns `Ok` if the pending request was successfully inserted otherwise `Err`.
 	pub(crate) fn insert_pending_call(
@@ -114,7 +114,7 @@ impl RequestManager {
 		}
 	}
 
-	/// Tries to insert a new batch request
+	/// Tries to insert a new batch request.
 	///
 	/// Returns `Ok` if the pending request was successfully inserted otherwise `Err`.
 	pub(crate) fn insert_pending_batch(
@@ -134,6 +134,7 @@ impl RequestManager {
 			Err(send_back)
 		}
 	}
+
 	/// Tries to insert a new pending subscription and reserves a slot for a "potential" unsubscription request.
 	///
 	/// Returns `Ok` if the pending request was successfully inserted otherwise `Err`.

core/src/client/async_client/mod.rs

@@ -542,7 +542,7 @@ async fn handle_backend_messages<S: TransportSenderT, R: TransportReceiverT>(
 
 	match message {
 		Some(Ok(ReceivedMessage::Pong)) => {
-			tracing::debug!("recv pong");
+			tracing::debug!("Received pong");
 		}
 		Some(Ok(ReceivedMessage::Bytes(raw))) => {
 			handle_recv_message(raw.as_ref(), manager, sender, max_notifs_per_subscription).await?;
@@ -551,12 +551,10 @@ async fn handle_backend_messages<S: TransportSenderT, R: TransportReceiverT>(
 			handle_recv_message(raw.as_ref(), manager, sender, max_notifs_per_subscription).await?;
 		}
 		Some(Err(e)) => {
-			tracing::error!("Error: {:?} terminating client", e);
 			return Err(Error::Transport(e.into()));
 		}
 		None => {
-			tracing::error!("[backend]: WebSocket receiver dropped; terminate client");
-			return Err(Error::Custom("WebSocket receiver dropped".into()));
+			return Err(Error::Custom("TransportReceiver dropped".into()));
 		}
 	}
 
@@ -564,49 +562,41 @@ async fn handle_backend_messages<S: TransportSenderT, R: TransportReceiverT>(
 }
 
 /// Handle frontend messages.
-///
-/// Returns an error if the main background loop should be terminated.
 async fn handle_frontend_messages<S: TransportSenderT>(
-	message: Option<FrontToBack>,
+	message: FrontToBack,
 	manager: &mut RequestManager,
 	sender: &mut S,
 	max_notifs_per_subscription: usize,
-) -> Result<(), Error> {
+) {
 	match message {
-		// User dropped the sender side of the channel.
-		// There is nothing to do just terminate.
-		None => {
-			return Err(Error::Custom("[backend]: frontend dropped; terminate client".into()));
-		}
-
-		Some(FrontToBack::Batch(batch)) => {
+		FrontToBack::Batch(batch) => {
 			if let Err(send_back) = manager.insert_pending_batch(batch.ids.clone(), batch.send_back) {
-				tracing::warn!("[backend]: batch request: {:?} already pending", batch.ids);
+				tracing::warn!("[backend]: Batch request already pending: {:?}", batch.ids);
 				let _ = send_back.send(Err(Error::InvalidRequestId));
-				return Ok(());
+				return;
 			}
 
 			if let Err(e) = sender.send(batch.raw).await {
-				tracing::warn!("[backend]: client batch request failed: {:?}", e);
+				tracing::warn!("[backend]: Batch request failed: {:?}", e);
 				manager.complete_pending_batch(batch.ids);
 			}
 		}
 		// User called `notification` on the front-end
-		Some(FrontToBack::Notification(notif)) => {
+		FrontToBack::Notification(notif) => {
 			if let Err(e) = sender.send(notif).await {
-				tracing::warn!("[backend]: client notif failed: {:?}", e);
+				tracing::warn!("[backend]: Notification failed: {:?}", e);
 			}
 		}
 		// User called `request` on the front-end
-		Some(FrontToBack::Request(request)) => match sender.send(request.raw).await {
+		FrontToBack::Request(request) => match sender.send(request.raw).await {
 			Ok(_) => manager.insert_pending_call(request.id, request.send_back).expect("ID unused checked above; qed"),
 			Err(e) => {
-				tracing::warn!("[backend]: client request failed: {:?}", e);
+				tracing::warn!("[backend]: Request failed: {:?}", e);
 				let _ = request.send_back.map(|s| s.send(Err(Error::Transport(e.into()))));
 			}
 		},
 		// User called `subscribe` on the front-end.
-		Some(FrontToBack::Subscribe(sub)) => match sender.send(sub.raw).await {
+		FrontToBack::Subscribe(sub) => match sender.send(sub.raw).await {
 			Ok(_) => manager
 				.insert_pending_subscription(
 					sub.subscribe_id,
@@ -616,13 +606,13 @@ async fn handle_frontend_messages<S: TransportSenderT>(
 				)
 				.expect("Request ID unused checked above; qed"),
 			Err(e) => {
-				tracing::warn!("[backend]: client subscription failed: {:?}", e);
+				tracing::warn!("[backend]: Subscription failed: {:?}", e);
 				let _ = sub.send_back.send(Err(Error::Transport(e.into())));
 			}
 		},
 		// User dropped a subscription.
-		Some(FrontToBack::SubscriptionClosed(sub_id)) => {
-			tracing::trace!("Closing subscription: {:?}", sub_id);
+		FrontToBack::SubscriptionClosed(sub_id) => {
+			tracing::trace!("[backend]: Closing subscription: {:?}", sub_id);
 			// NOTE: The subscription may have been closed earlier if
 			// the channel was full or disconnected.
 			if let Some(unsub) = manager
@@ -633,7 +623,7 @@ async fn handle_frontend_messages<S: TransportSenderT>(
 			}
 		}
 		// User called `register_notification` on the front-end.
-		Some(FrontToBack::RegisterNotification(reg)) => {
+		FrontToBack::RegisterNotification(reg) => {
 			let (subscribe_tx, subscribe_rx) = mpsc::channel(max_notifs_per_subscription);
 
 			if manager.insert_notification_handler(&reg.method, subscribe_tx).is_ok() {
@@ -642,13 +632,11 @@ async fn handle_frontend_messages<S: TransportSenderT>(
 				let _ = reg.send_back.send(Err(Error::MethodAlreadyRegistered(reg.method)));
 			}
 		}
-		// User dropped the notificationHandler for this method
-		Some(FrontToBack::UnregisterNotification(method)) => {
+		// User dropped the NotificationHandler for this method
+		FrontToBack::UnregisterNotification(method) => {
 			let _ = manager.remove_notification_handler(method);
 		}
 	}
-
-	Ok(())
 }
 
 /// Function being run in the background that processes messages from the frontend.
@@ -692,14 +680,18 @@ async fn background_task<S, R>(
 		match future::select(message_fut, submit_ping).await {
 			// Message received from the frontend.
 			Either::Left((Either::Left((frontend_value, backend)), _)) => {
-				if let Err(err) =
-					handle_frontend_messages(frontend_value, &mut manager, &mut sender, max_notifs_per_subscription)
-						.await
-				{
-					tracing::warn!("{:?}", err);
-					let _ = front_error.send(err);
+				let frontend_value = if let Some(value) = frontend_value {
+					value
+				} else {
+					// User dropped the sender side of the channel.
+					// There is nothing to do just terminate.
+					tracing::debug!("[backend]: Client dropped");
 					break;
-				}
+				};
+
+				handle_frontend_messages(frontend_value, &mut manager, &mut sender, max_notifs_per_subscription)
+					.await;
+
 				// Advance frontend, save backend.
 				message_fut = future::select(frontend.next(), backend);
 			}
@@ -713,7 +705,7 @@ async fn background_task<S, R>(
 				)
 				.await
 				{
-					tracing::warn!("{:?}", err);
+					tracing::error!("[backend]: {}", err);
 					let _ = front_error.send(err);
 					break;
 				}
@@ -722,8 +714,8 @@ async fn background_task<S, R>(
 			}
 			// Submit ping interval was triggered if enabled.
 			Either::Right((_, next_message_fut)) => {
-				if let Err(e) = sender.send_ping().await {
-					tracing::warn!("[backend]: client send ping failed: {:?}", e);
+				if let Err(err) = sender.send_ping().await {
+					tracing::error!("[backend]: Could not send ping frame: {}", err);
 					let _ = front_error.send(Error::Custom("Could not send ping frame".into()));
 					break;
 				}
@@ -731,6 +723,7 @@ async fn background_task<S, R>(
 			}
 		};
 	}
+
 	// Wake the `on_disconnect` method.
 	let _ = on_close.send(());
 	// Send close message to the server.

core/src/server/helpers.rs

@@ -83,7 +83,7 @@ impl<'a> io::Write for &'a mut BoundedWriter {
 /// Sink that is used to send back the result to the server for a specific method.
 #[derive(Clone, Debug)]
 pub struct MethodSink {
-	/// Channel sender
+	/// Channel sender.
 	tx: mpsc::UnboundedSender<String>,
 	/// Max response size in bytes for a executed call.
 	max_response_size: u32,
@@ -92,12 +92,12 @@ pub struct MethodSink {
 }
 
 impl MethodSink {
-	/// Create a new `MethodSink` with unlimited response size
+	/// Create a new `MethodSink` with unlimited response size.
 	pub fn new(tx: mpsc::UnboundedSender<String>) -> Self {
 		MethodSink { tx, max_response_size: u32::MAX, max_log_length: u32::MAX }
 	}
 
-	/// Create a new `MethodSink` with a limited response size
+	/// Create a new `MethodSink` with a limited response size.
 	pub fn new_with_limit(tx: mpsc::UnboundedSender<String>, max_response_size: u32, max_log_length: u32) -> Self {
 		MethodSink { tx, max_response_size, max_log_length }
 	}
@@ -112,7 +112,7 @@ impl MethodSink {
 		let json = match serde_json::to_string(&ErrorResponse::borrowed(error, id)) {
 			Ok(json) => json,
 			Err(err) => {
-				tracing::error!("Error serializing error message: {:?}", err);
+				tracing::error!("Error serializing response: {:?}", err);
 
 				return false;
 			}
@@ -128,7 +128,7 @@ impl MethodSink {
 		}
 	}
 
-	/// Helper for sending the general purpose `Error` as a JSON-RPC errors to the client
+	/// Helper for sending the general purpose `Error` as a JSON-RPC errors to the client.
 	pub fn send_call_error(&self, id: Id, err: Error) -> bool {
 		self.send_error(id, err.into())
 	}

core/src/server/rpc_module.rs

@@ -364,7 +364,7 @@ impl Methods {
 	) -> Result<T, Error> {
 		let params = params.to_rpc_params()?;
 		let req = Request::new(method.into(), Some(&params), Id::Number(0));
-		tracing::trace!("[Methods::call] Calling method: {:?}, params: {:?}", method, params);
+		tracing::trace!("[Methods::call] Method: {:?}, params: {:?}", method, params);
 		let (resp, _, _) = self.inner_call(req).await;
 
 		if resp.success {
@@ -406,10 +406,10 @@ impl Methods {
 	/// ```
 	pub async fn raw_json_request(
 		&self,
-		call: &str,
+		request: &str,
 	) -> Result<(MethodResponse, mpsc::UnboundedReceiver<String>), Error> {
-		tracing::trace!("[Methods::raw_json_request] {:?}", call);
-		let req: Request = serde_json::from_str(call)?;
+		tracing::trace!("[Methods::raw_json_request] Request: {:?}", request);
+		let req: Request = serde_json::from_str(request)?;
 		let (resp, rx, _) = self.inner_call(req).await;
 		Ok((resp, rx))
 	}
@@ -424,7 +424,7 @@ impl Methods {
 		let close_notify = bounded_subs.acquire().expect("u32::MAX permits is sufficient; qed");
 		let notify = bounded_subs.acquire().expect("u32::MAX permits is sufficient; qed");
 
-		let result = match self.method(&req.method).map(|c| &c.callback) {
+		let response = match self.method(&req.method).map(|c| &c.callback) {
 			None => MethodResponse::error(req.id, ErrorObject::from(ErrorCode::MethodNotFound)),
 			Some(MethodKind::Sync(cb)) => (cb)(id, params, usize::MAX),
 			Some(MethodKind::Async(cb)) => (cb)(id.into_owned(), params.into_owned(), 0, usize::MAX, None).await,
@@ -443,9 +443,9 @@ impl Methods {
 			Some(MethodKind::Unsubscription(cb)) => (cb)(id, params, 0, usize::MAX),
 		};
 
-		tracing::trace!("[Methods::inner_call]: method: `{}` result: {:?}", req.method, result);
+		tracing::trace!("[Methods::inner_call] Method: {}, response: {:?}", req.method, response);
 
-		(result, rx_sink, notify)
+		(response, rx_sink, notify)
 	}
 
 	/// Helper to create a subscription on the `RPC module` without having to spin up a server.
@@ -477,12 +477,10 @@ impl Methods {
 		let params = params.to_rpc_params()?;
 		let req = Request::new(sub_method.into(), Some(&params), Id::Number(0));
 
-		tracing::trace!("[Methods::subscribe] Calling subscription method: {:?}, params: {:?}", sub_method, params);
+		tracing::trace!("[Methods::subscribe] Method: {}, params: {:?}", sub_method, params);
 
 		let (response, rx, close_notify) = self.inner_call(req).await;
 
-		tracing::trace!("[Methods::subscribe] response {:?}", response);
-
 		let subscription_response = match serde_json::from_str::<Response<RpcSubscriptionId>>(&response.result) {
 			Ok(r) => r,
 			Err(_) => match serde_json::from_str::<ErrorResponse>(&response.result) {
@@ -728,7 +726,7 @@ impl<Context: Send + Sync + 'static> RpcModule<Context> {
 						Ok(sub_id) => sub_id,
 						Err(_) => {
 							tracing::warn!(
-								"unsubscribe call '{}' failed: couldn't parse subscription id={:?} request id={:?}",
+								"Unsubscribe call `{}` failed: couldn't parse subscription id={:?} request id={:?}",
 								unsubscribe_method_name,
 								params,
 								id
@@ -743,7 +741,7 @@ impl<Context: Send + Sync + 'static> RpcModule<Context> {
 
 					if !result {
 						tracing::warn!(
-							"unsubscribe call `{}` subscription key={:?} not an active subscription",
+							"Unsubscribe call `{}` subscription key={:?} not an active subscription",
 							unsubscribe_method_name,
 							key,
 						);
@@ -778,7 +776,7 @@ impl<Context: Send + Sync + 'static> RpcModule<Context> {
 
 					// The callback returns a `SubscriptionResult` for better ergonomics and is not propagated further.
 					if callback(params, sink, ctx.clone()).is_err() {
-						tracing::warn!("subscribe call `{}` failed", subscribe_method_name);
+						tracing::warn!("Subscribe call `{}` failed", subscribe_method_name);
 					}
 
 					let id = id.clone().into_owned();

http-server/src/server.rs

@@ -487,12 +487,12 @@ impl<L: Logger> ServiceData<L> {
 		let maybe_origin = http_helpers::read_header_value(request.headers(), "origin");
 
 		if let Err(e) = acl.verify_host(host) {
-			tracing::warn!("Denied request: {:?}", e);
+			tracing::warn!("Denied request: {}", e);
 			return response::host_not_allowed();
 		}
 
 		if let Err(e) = acl.verify_origin(maybe_origin, host) {
-			tracing::warn!("Denied request: {:?}", e);
+			tracing::warn!("Denied request: {}", e);
 			return response::origin_rejected(maybe_origin);
 		}
 
@@ -936,7 +936,7 @@ async fn execute_call<L: Logger>(c: Call<'_, L>) -> MethodResponse {
 						r
 					}
 					Err(err) => {
-						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err);
+						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {}", err);
 						MethodResponse::error(id, ErrorObject::from(ErrorCode::ServerIsBusy))
 					}
 				}
@@ -951,7 +951,7 @@ async fn execute_call<L: Logger>(c: Call<'_, L>) -> MethodResponse {
 						(callback)(id, params, conn_id, max_response_body_size as usize, Some(guard)).await
 					}
 					Err(err) => {
-						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err);
+						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {}", err);
 						MethodResponse::error(id, ErrorObject::from(ErrorCode::ServerIsBusy))
 					}
 				}

tests/tests/integration_tests.rs

@@ -506,10 +506,10 @@ async fn ws_server_notify_client_on_disconnect() {
 	server_handle.stop().unwrap().await;
 
 	// The `on_disconnect()` method returned.
-	let _ = dis_rx.await.unwrap();
+	dis_rx.await.unwrap();
 
 	// Multiple `on_disconnect()` calls did not block.
-	let _ = multiple_rx.await.unwrap();
+	multiple_rx.await.unwrap();
 }
 
 #[tokio::test]

ws-server/src/server.rs

@@ -126,12 +126,12 @@ impl<L: Logger> Server<L> {
 			match connections.select_with(&mut incoming).await {
 				Ok((socket, _addr)) => {
 					if let Err(e) = socket.set_nodelay(true) {
-						tracing::error!("Could not set NODELAY on socket: {:?}", e);
+						tracing::warn!("Could not set NODELAY on socket: {:?}", e);
 						continue;
 					}
 
 					if connections.count() >= self.cfg.max_connections as usize {
-						tracing::warn!("Too many connections. Try again in a while.");
+						tracing::warn!("Too many connections. Please try again later.");
 						connections.add(Box::pin(handshake(socket, HandshakeResponse::Reject { status_code: 429 })));
 						continue;
 					}
@@ -264,7 +264,7 @@ async fn handshake<L: Logger>(socket: tokio::net::TcpStream, mode: HandshakeResp
 					server.send_response(&accept).await?;
 				}
 				Err(err) => {
-					tracing::warn!("Rejected connection: {:?}", err);
+					tracing::warn!("Rejected connection: {} error: {:?}", conn_id, err);
 					let reject = Response::Reject { status_code: 403 };
 					server.send_response(&reject).await?;
 
@@ -360,7 +360,7 @@ async fn background_task<L: Logger>(input: BackgroundTask<'_, L>) -> Result<(),
 				Either::Left((Some(response), ping)) => {
 					// If websocket message send fail then terminate the connection.
 					if let Err(err) = send_ws_message(&mut sender, response).await {
-						tracing::warn!("WS send error: {}; terminate connection", err);
+						tracing::error!("Terminate connection: WS send error: {}", err);
 						break;
 					}
 					rx_item = rx.next();
@@ -372,7 +372,7 @@ async fn background_task<L: Logger>(input: BackgroundTask<'_, L>) -> Result<(),
 				// Handle timer intervals.
 				Either::Right((_, next_rx)) => {
 					if let Err(err) = send_ws_ping(&mut sender).await {
-						tracing::warn!("WS send ping error: {}; terminate connection", err);
+						tracing::error!("Terminate connection: WS send ping error: {}", err);
 						break;
 					}
 					rx_item = next_rx;
@@ -403,7 +403,7 @@ async fn background_task<L: Logger>(input: BackgroundTask<'_, L>) -> Result<(),
 				loop {
 					match receiver.receive(&mut data).await? {
 						soketto::Incoming::Data(d) => break Ok(d),
-						soketto::Incoming::Pong(_) => tracing::debug!("recv pong"),
+						soketto::Incoming::Pong(_) => tracing::debug!("Received pong"),
 						soketto::Incoming::Closed(_) => {
 							// The closing reason is already logged by `soketto` trace log level.
 							// Return the `Closed` error to avoid logging unnecessary warnings on clean shutdown.
@@ -418,13 +418,13 @@ async fn background_task<L: Logger>(input: BackgroundTask<'_, L>) -> Result<(),
 			if let Err(err) = method_executors.select_with(Monitored::new(receive, &stop_server)).await {
 				match err {
 					MonitoredError::Selector(SokettoError::Closed) => {
-						tracing::debug!("WS transport: remote peer terminated the connection: {}", conn_id);
+						tracing::debug!("WS transport: Remote peer terminated the connection: {}", conn_id);
 						sink.close();
 						break Ok(());
 					}
 					MonitoredError::Selector(SokettoError::MessageTooLarge { current, maximum }) => {
 						tracing::warn!(
-							"WS transport error: outgoing message is too big error ({} bytes, max is {})",
+							"WS transport error: Request length: {} exceeded max limit: {} bytes",
 							current,
 							maximum
 						);
@@ -433,7 +433,7 @@ async fn background_task<L: Logger>(input: BackgroundTask<'_, L>) -> Result<(),
 					}
 					// These errors can not be gracefully handled, so just log them and terminate the connection.
 					MonitoredError::Selector(err) => {
-						tracing::debug!("WS error: {}; terminate connection {}", err, conn_id);
+						tracing::error!("Terminate connection {}: WS error: {}", conn_id, err);
 						sink.close();
 						break Err(err.into());
 					}
@@ -795,7 +795,7 @@ async fn send_ws_message(
 }
 
 async fn send_ws_ping(sender: &mut Sender<BufReader<BufWriter<Compat<TcpStream>>>>) -> Result<(), Error> {
-	tracing::debug!("send ping");
+	tracing::debug!("Send ping");
 	// Submit empty slice as "optional" parameter.
 	let slice: &[u8] = &[];
 	// Byte slice fails if the provided slice is larger than 125 bytes.
@@ -950,7 +950,7 @@ async fn execute_call<L: Logger>(c: Call<'_, L>) -> MethodResult {
 						MethodResult::SendAndLogger(r)
 					}
 					Err(err) => {
-						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err);
+						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {}", err);
 						let response = MethodResponse::error(id, ErrorObject::from(ErrorCode::ServerIsBusy));
 						MethodResult::SendAndLogger(response)
 					}
@@ -969,7 +969,7 @@ async fn execute_call<L: Logger>(c: Call<'_, L>) -> MethodResult {
 						MethodResult::SendAndLogger(response)
 					}
 					Err(err) => {
-						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err);
+						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {}", err);
 						let response = MethodResponse::error(id, ErrorObject::from(ErrorCode::ServerIsBusy));
 						MethodResult::SendAndLogger(response)
 					}
@@ -991,7 +991,7 @@ async fn execute_call<L: Logger>(c: Call<'_, L>) -> MethodResult {
 						}
 					}
 					Err(err) => {
-						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {:?}", err);
+						tracing::error!("[Methods::execute_with_resources] failed to lock resources: {}", err);
 						let response = MethodResponse::error(id, ErrorObject::from(ErrorCode::ServerIsBusy));
 						MethodResult::SendAndLogger(response)
 					}