From 8cd5b60b4d2058342e52452f19ec1035baffa44b Mon Sep 17 00:00:00 2001 From: Brian Pearce Date: Tue, 12 Dec 2023 15:51:03 +0100 Subject: [PATCH] refactor: increase trace verbosity in ffis (#6035) Description --- Add a bunch more trace logging in chat ffi. Add logging verbosity option in wallet ffi. Motivation and Context --- Mo logging mo fun. But really it's for helping during debugging parties. How Has This Been Tested? --- CI What process can a PR reviewer use to test or verify this change? --- Does it make sense? Breaking Changes --- - [x] None - [ ] Requires data directory on base node to be deleted - [ ] Requires hard fork - [ ] Other - Please specify Co-authored-by: SW van Heerden --- .../contacts/src/chat_client/src/database.rs | 10 ++- .../src/chat_client/src/networking.rs | 8 ++- .../contacts/src/contacts_service/mod.rs | 1 + .../contacts/src/contacts_service/service.rs | 71 +++++++++++++++---- 4 files changed, 74 insertions(+), 16 deletions(-) diff --git a/base_layer/contacts/src/chat_client/src/database.rs b/base_layer/contacts/src/chat_client/src/database.rs index 9370fadb77..3b58233a07 100644 --- a/base_layer/contacts/src/chat_client/src/database.rs +++ b/base_layer/contacts/src/chat_client/src/database.rs @@ -23,6 +23,7 @@ use std::path::{Path, PathBuf}; use diesel::{Connection, SqliteConnection}; +use log::trace; use tari_common_sqlite::{ connection::{DbConnection, DbConnectionUrl}, error::StorageError as SqliteStorageError, @@ -32,16 +33,21 @@ use tari_storage::lmdb_store::{LMDBBuilder, LMDBConfig}; use crate::error::StorageError; +const LOG_TARGET: &str = "contacts::chat_client::database"; + pub fn connect_to_db(db_path: PathBuf) -> Result, SqliteStorageError> { let url: DbConnectionUrl = DbConnectionUrl::File(db_path); let connection = DbConnection::connect_url(&url)?; + trace!(target: LOG_TARGET, "Connected to chat storage db {:?}", url); Ok(ContactsServiceSqliteDatabase::init(connection)) } pub fn create_chat_storage(db_file_path: &Path) -> Result<(), StorageError> { // Create the storage db std::fs::create_dir_all(db_file_path.parent().ok_or(StorageError::FilePathError)?)?; - let _db = SqliteConnection::establish(db_file_path.as_os_str().to_str().ok_or(StorageError::FilePathError)?)?; + let db_path = db_file_path.as_os_str().to_str().ok_or(StorageError::FilePathError)?; + let _db = SqliteConnection::establish(db_path)?; + trace!(target: LOG_TARGET, "Created chat storage db {}", db_path); Ok(()) } @@ -55,5 +61,7 @@ pub fn create_peer_storage(base_path: &PathBuf) -> Result<(), StorageError> { .add_database("peerdb", lmdb_zero::db::CREATE) .build()?; + trace!(target: LOG_TARGET, "Created chat peer db {:?}", base_path.join("peerdb")); + Ok(()) } diff --git a/base_layer/contacts/src/chat_client/src/networking.rs b/base_layer/contacts/src/chat_client/src/networking.rs index e885a508b0..fa84a20e9f 100644 --- a/base_layer/contacts/src/chat_client/src/networking.rs +++ b/base_layer/contacts/src/chat_client/src/networking.rs @@ -22,6 +22,7 @@ use std::{str::FromStr, sync::Arc, time::Duration}; +use log::trace; use minotari_app_utilities::{identity_management, identity_management::load_from_json}; // Re-exports pub use tari_comms::{ @@ -46,6 +47,8 @@ use crate::{ error::NetworkingError, }; +const LOG_TARGET: &str = "contacts::chat_client::networking"; + pub async fn start( node_identity: Arc, config: ApplicationConfig, @@ -60,7 +63,8 @@ pub async fn start( let mut p2p_config = config.chat_client.p2p.clone(); let tor_identity = load_from_json(&config.chat_client.tor_identity_file)?; - p2p_config.transport.tor.identity = tor_identity; + p2p_config.transport.tor.identity = tor_identity.clone(); + trace!(target: LOG_TARGET, "loaded chat tor identity {:?}", tor_identity); let fut = StackBuilder::new(shutdown_signal) .add_initializer(P2pInitializer::new( @@ -114,10 +118,12 @@ pub async fn start( TransportType::Tcp => {}, // Do not overwrite TCP public_address in the base_node_id! _ => { identity_management::save_as_json(&config.chat_client.identity_file, &*comms.node_identity())?; + trace!(target: LOG_TARGET, "save chat identity file"); }, }; if let Some(hs) = comms.hidden_service() { identity_management::save_as_json(&config.chat_client.tor_identity_file, hs.tor_identity())?; + trace!(target: LOG_TARGET, "resave the chat tor identity {:?}", hs.tor_identity()); } handles.register(comms); diff --git a/base_layer/contacts/src/contacts_service/mod.rs b/base_layer/contacts/src/contacts_service/mod.rs index 6379933ec2..319a827381 100644 --- a/base_layer/contacts/src/contacts_service/mod.rs +++ b/base_layer/contacts/src/contacts_service/mod.rs @@ -83,6 +83,7 @@ impl ServiceInitializer for ContactsServiceInitializer where T: ContactsBackend + 'static { async fn initialize(&mut self, context: ServiceInitializerContext) -> Result<(), ServiceInitializationError> { + trace!(target: LOG_TARGET, "Initializing ContactsServiceInitializer"); let (liveness_tx, liveness_rx) = reply_channel::unbounded(); let (publisher, _) = broadcast::channel(250); let (message_publisher, _) = broadcast::channel(250); diff --git a/base_layer/contacts/src/contacts_service/service.rs b/base_layer/contacts/src/contacts_service/service.rs index 955990abb1..87f6379dbb 100644 --- a/base_layer/contacts/src/contacts_service/service.rs +++ b/base_layer/contacts/src/contacts_service/service.rs @@ -302,19 +302,46 @@ where T: ContactsBackend + 'static let ob_message = OutboundDomainMessage::from(MessageDispatch::Message(message.clone())); message.stored_at = Utc::now().naive_utc().timestamp() as u64; - self.db.save_message(message)?; - self.deliver_message(address, ob_message).await?; + match self.db.save_message(message) { + Ok(_) => { + if let Err(e) = self.deliver_message(address.clone(), ob_message).await { + trace!(target: LOG_TARGET, "Failed to broadcast a message {} over the network: {}", address, e); + } + }, + Err(e) => { + trace!(target: LOG_TARGET, "Failed to save the message locally, did not broadcast the message to the network"); + return Err(e.into()); + }, + } + trace!(target: LOG_TARGET, "Sent message to {} successfully", address); Ok(ContactsServiceResponse::MessageSent) }, ContactsServiceRequest::SendReadConfirmation(address, confirmation) => { let msg = OutboundDomainMessage::from(MessageDispatch::ReadConfirmation(confirmation.clone())); trace!(target: LOG_TARGET, "Sending read confirmation with details: message_id: {:?}, timestamp: {:?}", confirmation.message_id, confirmation.timestamp); - self.deliver_message(address, msg).await?; - - self.db - .confirm_message(confirmation.message_id.clone(), None, Some(confirmation.timestamp))?; + match self.deliver_message(address.clone(), msg).await { + Ok(_) => { + trace!(target: LOG_TARGET, "Read confirmation broadcast for message_id: {:?} to {}", confirmation.message_id, address); + match self.db.confirm_message( + confirmation.message_id.clone(), + None, + Some(confirmation.timestamp), + ) { + Ok(_) => { + trace!(target: LOG_TARGET, "Read confirmation locally saved for message_id: {:?} to {}", confirmation.message_id, address); + }, + Err(e) => { + trace!(target: LOG_TARGET, "Failed to save the read confirmation locally for message_id: {:?} with error {}", confirmation.message_id, e); + }, + } + }, + Err(e) => { + trace!(target: LOG_TARGET, "Failed to broadcast the read confirmation of message_id: {:?} to {} with error {}", confirmation.message_id, address, e); + return Err(e); + }, + } Ok(ContactsServiceResponse::ReadConfirmationSent) }, @@ -398,9 +425,13 @@ where T: ContactsBackend + 'static &mut self, msg: DomainMessage>, ) -> Result<(), ContactsServiceError> { + trace!(target: LOG_TARGET, "Handling incoming chat message dispatch {:?} from peer {}", msg, msg.source_peer.public_key); + let msg_inner = match &msg.inner { Ok(msg) => msg.clone(), Err(e) => { + debug!(target: LOG_TARGET, "Banning peer {} for illformed message", msg.source_peer.public_key); + self.connectivity .ban_peer( msg.source_peer.node_id.clone(), @@ -555,19 +586,26 @@ where T: ContactsBackend + 'static stored_at: EpochTime::now().as_u64(), ..message }; + trace!(target: LOG_TARGET, "Handling chat message {:?}", our_message); match self.db.save_message(our_message.clone()) { Ok(..) => { - let _msg = self + if let Err(e) = self .message_publisher - .send(Arc::new(MessageDispatch::Message(our_message.clone()))); + .send(Arc::new(MessageDispatch::Message(our_message.clone()))) + { + debug!(target: LOG_TARGET, "Failed to re-broadcast chat message internally: {}", e); + } // Send a delivery notification self.create_and_send_delivery_confirmation_for_msg(&our_message).await?; Ok(()) }, - Err(e) => Err(e.into()), + Err(e) => { + trace!(target: LOG_TARGET, "Failed to save incoming message to the db {}", e); + Err(e.into()) + }, } } @@ -576,17 +614,21 @@ where T: ContactsBackend + 'static message: &Message, ) -> Result<(), ContactsServiceError> { let address = &message.address; - let delivery_time = EpochTime::now().as_u64(); let confirmation = MessageDispatch::DeliveryConfirmation(Confirmation { message_id: message.message_id.clone(), - timestamp: delivery_time, + timestamp: message.stored_at, }); let msg = OutboundDomainMessage::from(confirmation); + trace!(target: LOG_TARGET, "Sending a delivery notification {:?}", msg); self.deliver_message(address.clone(), msg).await?; - self.db - .confirm_message(message.message_id.clone(), Some(delivery_time), None)?; + if let Err(e) = self + .db + .confirm_message(message.message_id.clone(), Some(message.stored_at), None) + { + trace!(target: LOG_TARGET, "Failed to store the delivery confirmation in the db: {}", e); + } Ok(()) } @@ -622,7 +664,7 @@ where T: ContactsBackend + 'static match self.get_online_status(&contact).await { Ok(ContactOnlineStatus::Online) => { - info!(target: LOG_TARGET, "Chat message being sent directed"); + info!(target: LOG_TARGET, "Chat message being sent direct"); let mut comms_outbound = self.dht.outbound_requester(); comms_outbound @@ -636,6 +678,7 @@ where T: ContactsBackend + 'static }, Err(e) => return Err(e), _ => { + info!(target: LOG_TARGET, "Chat message being sent via closest broadcast"); let mut comms_outbound = self.dht.outbound_requester(); comms_outbound .closest_broadcast(address.public_key().clone(), encryption, vec![], message)