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 <[email protected]>
tari-project · Dec 12, 2023 · 8cd5b60 · 8cd5b60
1 parent 851cb00
commit 8cd5b60
Show file tree

Hide file tree

Showing 4 changed files with 74 additions and 16 deletions.
diff --git 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<ContactsServiceSqliteDatabase<DbConnection>, 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
@@ -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<NodeIdentity>,
     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
@@ -83,6 +83,7 @@ impl<T> ServiceInitializer for ContactsServiceInitializer<T>
 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
@@ -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<proto::MessageDispatch, prost::DecodeError>>,
     ) -> 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)