added error logs and debug

clients/stellar-relay-lib/Cargo.toml

@@ -14,6 +14,7 @@ env_logger = "0.9.0"
 serial_test = "0.9.0"
 
 [dependencies]
+hex = "0.4.3"
 log = {version = "0.4.14"}
 
 base64 = "0.13.0"

clients/stellar-relay-lib/examples/connect.rs

@@ -1,9 +1,6 @@
 use stellar_relay_lib::{
 	connect_to_stellar_overlay_network,
-	sdk::{
-		types::{ScpStatementPledges, StellarMessage},
-		XdrCodec,
-	},
+	sdk::types::{ScpStatementPledges, StellarMessage},
 	StellarOverlayConfig, StellarRelayMessage,
 };
 
@@ -33,8 +30,9 @@ async fn main() -> Result<(), Box<dyn std::error::Error>> {
 	while let Some(relay_message) = overlay_connection.listen().await {
 		match relay_message {
 			StellarRelayMessage::Connect { pub_key, node_info } => {
-				let pub_key_xdr = pub_key.to_xdr();
-				log::info!("Connected to Stellar Node: {:?}", base64::encode(pub_key_xdr));
+				let pub_key = pub_key.to_encoding();
+				let pub_key = std::str::from_utf8(&pub_key).expect("should work?");
+				log::info!("Connected to Stellar Node: {pub_key}");
 				log::info!("{:?}", node_info);
 			},
 			StellarRelayMessage::Data { p_id: _, msg_type, msg } => match *msg {

clients/stellar-relay-lib/src/connection/authentication/authentication.rs

@@ -1,5 +1,8 @@
 use rand::Rng;
-use std::collections::HashMap;
+use std::{
+	collections::HashMap,
+	fmt::{Debug, Formatter},
+};
 use substrate_stellar_sdk::{
 	types::{AuthCert, Curve25519Public, HmacSha256Mac},
 	Curve25519Secret, SecretKey,
@@ -19,6 +22,29 @@ pub struct ConnectionAuth {
 	auth_cert_expiration: u64,
 }
 
+impl Debug for ConnectionAuth {
+	fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+		let pub_key = &self.pub_key_ecdh;
+		let pub_key = hex::encode(&pub_key.key);
+
+		let network_hash = &self.network_hash;
+		let network_hash = hex::encode(&network_hash);
+
+		let is_exist = &self.auth_cert.is_some();
+
+		f.debug_struct("ConnectionAuth")
+			.field("keypair", &"****")
+			.field("secret_key_ecdh", &"****")
+			.field("pub_key_ecdh", &pub_key)
+			.field("network_hash", &network_hash)
+			.field("we_called_remote_shared_keys", &"****")
+			.field("remote_called_us_shared_keys", &"****")
+			.field("auth_cert_exists", is_exist)
+			.field("auth_cert_expiration", &self.auth_cert_expiration)
+			.finish()
+	}
+}
+
 impl ConnectionAuth {
 	pub fn new(
 		network: &BinarySha256Hash,

clients/stellar-relay-lib/src/connection/connector/connector.rs

@@ -1,3 +1,4 @@
+use std::fmt::{Debug, Formatter};
 use substrate_stellar_sdk::{
 	types::{AuthenticatedMessageV0, Curve25519Public, HmacSha256Mac, MessageType},
 	XdrCodec,
@@ -38,14 +39,27 @@ pub struct Connector {
 	relay_message_sender: mpsc::Sender<StellarRelayMessage>,
 }
 
+impl Debug for Connector {
+	fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+		let is_hmac_keys_filled = self.hmac_keys.is_some();
+		f.debug_struct("Connector")
+			.field("local", &self.local)
+			.field("remote", &self.remote_info)
+			.field("hmac_keys_exist", &is_hmac_keys_filled)
+			.field("connection_auth", &self.connection_auth)
+			.field("timeout_in_secs", &self.timeout_in_secs)
+			.field("retries", &self.retries)
+			.field("receive_tx_messages", &self.receive_tx_messages)
+			.field("receive_scp_messages", &self.receive_scp_messages)
+			.field("handshake_state", &self.handshake_state)
+			.field("flow_controller", &self.flow_controller)
+			.finish()
+	}
+}
+
 impl Drop for Connector {
 	fn drop(&mut self) {
-		log::trace!(
-			"dropped Connector: \n local: {:?} \n remote_info: {:?} \n auth: {:?}",
-			self.local,
-			self.remote_info,
-			self.connection_auth.pub_key_ecdh()
-		);
+		log::trace!("dropped Connector: {:?}", self);
 	}
 }
 
@@ -57,8 +71,8 @@ impl Connector {
 		body: &[u8],
 	) -> Result<(), Error> {
 		let remote_info = self.remote_info.as_ref().ok_or(Error::NoRemoteInfo)?;
-		log::debug!(
-			"remote sequence: {}, auth message sequence: {}",
+		log::trace!(
+			"Auth Verification: remote sequence: {}, auth message sequence: {}",
 			remote_info.sequence(),
 			auth_msg.sequence
 		);

clients/stellar-relay-lib/src/connection/connector/message_handler.rs

@@ -17,8 +17,6 @@ impl Connector {
 		let (proc_id, data) = xdr;
 		let (auth_msg, msg_type) = parse_authenticated_message(&data)?;
 
-		log::debug!("proc_id: {} processing {:?}", proc_id, msg_type);
-
 		match msg_type {
 			MessageType::Transaction | MessageType::FloodAdvert if !self.receive_tx_messages() => {
 				self.increment_remote_sequence()?;
@@ -34,7 +32,9 @@ impl Connector {
 				if self.is_handshake_created() {
 					self.verify_auth(&auth_msg, &data[4..(data.len() - 32)])?;
 					self.increment_remote_sequence()?;
-					log::trace!("proc_id: {}, auth message verified", proc_id);
+					log::trace!(
+						"proc_id: {proc_id} Processing {msg_type:?} message: auth verified"
+					);
 				}
 
 				self.process_stellar_message(proc_id, auth_msg.message, msg_type).await?;
@@ -69,10 +69,10 @@ impl Connector {
 				self.process_auth_message().await?;
 			},
 
-			StellarMessage::SendMore(_) => {
-				log::info!("SendMore message received from overlay");
-			},
 			other => {
+				log::trace!(
+					"proc_id: {p_id} Processing {msg_type:?} message: received from overlay"
+				);
 				self.send_to_user(StellarRelayMessage::Data {
 					p_id,
 					msg_type,
@@ -92,8 +92,8 @@ impl Connector {
 
 		self.handshake_completed();
 
-		log::info!("Handshake completed");
 		if let Some(remote) = self.remote() {
+			log::debug!("Processing auth message: sending connect message: {remote:?}");
 			self.send_to_user(StellarRelayMessage::Connect {
 				pub_key: remote.pub_key().clone(),
 				node_info: remote.node().clone(),
@@ -105,7 +105,7 @@ impl Connector {
 				remote.node().overlay_version,
 			);
 		} else {
-			log::warn!("No remote overlay version after handshake.");
+			log::warn!("Processing auth message: No remote overlay version after handshake.");
 		}
 
 		self.check_to_send_more(MessageType::Auth).await

clients/stellar-relay-lib/src/connection/connector/message_sender.rs

@@ -19,7 +19,6 @@ impl Connector {
 			return Ok(())
 		}
 
-		log::debug!("Sending Send More message...");
 		let msg = StellarMessage::SendMore(SendMore { num_messages: MAX_FLOOD_MSG_CAP });
 		self.send_stellar_message(msg).await
 	}

clients/stellar-relay-lib/src/connection/flow_controller.rs

@@ -2,7 +2,7 @@ use substrate_stellar_sdk::types::MessageType;
 
 pub const MAX_FLOOD_MSG_CAP: u32 = 2000;
 
-#[derive(Default)]
+#[derive(Debug, Default)]
 pub struct FlowController {
 	enabled: bool,
 	flood_msg_cap: u32,

clients/stellar-relay-lib/src/connection/helper.rs

@@ -6,6 +6,19 @@ use substrate_stellar_sdk::{
 	SecretKey, XdrCodec,
 };
 
+/// a helpful macro to unwrap an `Ok` or return immediately.
+macro_rules! log_error {
+	// expression, return value, extra log
+	($res:expr, $log:expr) => {
+		$res.map_err(|e| {
+			log::error!("{:?}: {e:?}", $log);
+			e
+		})?;
+	};
+}
+
+pub(crate) use log_error;
+
 /// Returns a new BigNumber with a pseudo-random value equal to or greater than 0 and less than 1.
 pub fn generate_random_nonce() -> Uint256 {
 	let mut rng = rand::thread_rng();

clients/stellar-relay-lib/src/connection/mod.rs

@@ -12,6 +12,7 @@ pub mod xdr_converter;
 
 pub(crate) use connector::*;
 pub use error::Error;
+pub use helper::*;
 pub use overlay_connection::*;
 use serde::Serialize;
 use std::fmt::{Debug, Formatter};

clients/stellar-relay-lib/src/connection/overlay_connection.rs

@@ -61,27 +61,34 @@ impl StellarOverlayConnection {
 			let mut retries = 0;
 			while retries < self.max_retries {
 				log::info!(
-					"Connection timed out. Reconnecting to {:?}...",
+					"Overlay Connection: timed out. Reconnecting to {:?}...",
 					&self.conn_info.address
 				);
-				if let Ok(new_user) = StellarOverlayConnection::connect(
+
+				match StellarOverlayConnection::connect(
 					self.local_node.clone(),
 					self.conn_info.clone(),
 				)
 				.await
 				{
-					self.max_retries = new_user.max_retries;
-					self.actions_sender = new_user.actions_sender;
-					self.relay_message_receiver = new_user.relay_message_receiver;
-					log::info!("Reconnected to {:?}!", &self.conn_info.address);
-					return self.relay_message_receiver.recv().await
-				} else {
-					retries += 1;
-					log::error!(
-						"Failed to reconnect! # of retries left: {}. Retrying in 3 seconds...",
+					Ok(new_user) => {
+						self.max_retries = new_user.max_retries;
+						self.actions_sender = new_user.actions_sender;
+						self.relay_message_receiver = new_user.relay_message_receiver;
+						log::info!(
+							"Overlay Connection: reconnected to {:?}",
+							&self.conn_info.address
+						);
+						return self.relay_message_receiver.recv().await
+					},
+					Err(e) => {
+						retries += 1;
+						log::error!(
+						"Overlay Connection: failed to reconnect: {e:?}\n # of retries left: {}. Retrying in 3 seconds...",
 						self.max_retries
 					);
-					tokio::time::sleep(Duration::from_secs(3)).await;
+						tokio::time::sleep(Duration::from_secs(3)).await;
+					},
 				}
 			}
 		}
@@ -94,6 +101,9 @@ impl StellarOverlayConnection {
 		local_node: NodeInfo,
 		conn_info: ConnectionInfo,
 	) -> Result<StellarOverlayConnection, Error> {
+		log::info!("Connecting to: {}:{}", conn_info.address, conn_info.port);
+		log::trace!("Connecting to: {conn_info:?}");
+
 		let retries = conn_info.retries;
 		let timeout_in_secs = conn_info.timeout_in_secs;
 		// split the stream for easy handling of read and write

clients/stellar-relay-lib/src/connection/services.rs

@@ -2,6 +2,7 @@ use crate::{
 	connection::{
 		connector::{Connector, ConnectorActions},
 		helper::time_now,
+		log_error,
 		xdr_converter::get_xdr_message_length,
 	},
 	Error, StellarRelayMessage,
@@ -183,26 +184,29 @@ pub(crate) async fn receiving_service(
 				// then check the size of next stellar message.
 				// If it's not enough, skip it.
 				let expect_msg_len = next_message_length(&mut r_stream).await;
-				log::trace!("proc_id: {} The next message length: {}", proc_id, expect_msg_len);
+				log::trace!("proc_id: {proc_id} The next message length: {expect_msg_len}");
 
 				if expect_msg_len == 0 {
 					// there's nothing to read; wait for the next iteration
-					log::info!("WARNING!!! NOTHING TO READ!!!!");
+					log::trace!("proc_id: {proc_id} nothing left to read; wait for next loop");
 					continue
 				}
 
 				// let's start reading the actual stellar message.
 				readbuf = vec![0; expect_msg_len];
 
-				read_message(
-					&mut r_stream,
-					&actions_sender,
-					&mut lack_bytes_from_prev,
-					&mut proc_id,
-					&mut readbuf,
-					expect_msg_len,
-				)
-				.await?;
+				log_error!(
+					read_message(
+						&mut r_stream,
+						&actions_sender,
+						&mut lack_bytes_from_prev,
+						&mut proc_id,
+						&mut readbuf,
+						expect_msg_len,
+					)
+					.await,
+					format!("proc_id: {proc_id} Failed to read message")
+				);
 			},
 
 			Ok(Ok(_)) => {
@@ -219,14 +223,13 @@ pub(crate) async fn receiving_service(
 				.await?;
 			},
 			Ok(Err(e)) => {
-				log::error!("read ERROR! {:?}", e);
+				log::error!("proc_id: {proc_id} Error occurred when reading the stream: {e:?}");
 				return Err(Error::ConnectionFailed(e.to_string()))
 			},
 			Err(elapsed) => {
 				log::error!(
-					"{} for reading messages from Stellar Node. Retry: {}",
-					elapsed.to_string(),
-					retry
+					"proc_id: {proc_id} {} for reading messages from Stellar Node. Retry: {retry}",
+					elapsed.to_string()
 				);
 
 				if retry >= retries {
@@ -248,8 +251,8 @@ async fn _connection_handler(
 	match actions {
 		// start the connection to Stellar node with a 'hello'
 		ConnectorActions::SendHello => {
-			log::info!("Starting Handshake with Hello.");
 			let msg = connector.create_hello_message(time_now())?;
+			log::trace!("Sending Hello Message...{:?}", msg);
 			w_stream.write_all(&msg).await.map_err(|e| Error::WriteFailed(e.to_string()))?;
 		},
 
@@ -288,9 +291,8 @@ pub(crate) async fn connection_handler(
 		match timeout(Duration::from_secs(connector.timeout_in_secs), actions_receiver.recv()).await
 		{
 			Ok(Some(ConnectorActions::Disconnect)) => {
-				log::info!("Disconnecting TCP stream...");
 				w_stream.shutdown().await.map_err(|e| {
-					log::error!("failed to shutdown write half of stream: {:?}", e);
+					log::error!("Failed to shutdown write half of stream: {:?}", e);
 
 					Error::ConnectionFailed("Failed to disconnect tcp stream".to_string())
 				})?;
@@ -302,7 +304,10 @@ pub(crate) async fn connection_handler(
 
 			Ok(Some(action)) => {
 				timeout_counter = 0;
-				_connection_handler(action, &mut connector, &mut w_stream).await?;
+				log_error!(
+					_connection_handler(action, &mut connector, &mut w_stream).await,
+					format!("connection failed")
+				);
 			},
 
 			Ok(None) => {

clients/stellar-relay-lib/src/node/mod.rs

@@ -21,15 +21,12 @@ pub struct NodeInfo {
 
 impl Debug for NodeInfo {
 	fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
-		write!(
-			f,
-			"NodeInfo {{ ledger_version: {}, overlay_version: {}, overlay_min_version: {}, \
-			version_str: {} }}",
-			self.ledger_version,
-			self.overlay_version,
-			self.overlay_min_version,
-			String::from_utf8_lossy(&self.version_str),
-		)
+		f.debug_struct("NodeInfo")
+			.field("ledger_version", &self.ledger_version)
+			.field("overlay_version", &self.overlay_version)
+			.field("overlay_min_version", &self.overlay_min_version)
+			.field("version_str", &String::from_utf8_lossy(&self.version_str))
+			.finish()
 	}
 }