cherry-pick: JD debug logging from #162 (fixes #167)

src/jd_client/job_declarator/message_handler.rs

@@ -1,4 +1,4 @@
-use super::JobDeclarator;
+use super::{ErrorDetails, JobDeclarator};
 use roles_logic_sv2::{
     handlers::{job_declaration::ParseServerJobDeclarationMessages, SendTo_},
     job_declaration_sv2::{
@@ -9,6 +9,7 @@ use roles_logic_sv2::{
 };
 pub type SendTo = SendTo_<JobDeclaration<'static>, ()>;
 use roles_logic_sv2::errors::Error;
+use tracing::{debug, error};
 
 impl ParseServerJobDeclarationMessages for JobDeclarator {
     fn handle_allocate_mining_job_token_success(
@@ -30,8 +31,16 @@ impl ParseServerJobDeclarationMessages for JobDeclarator {
 
     fn handle_declare_mining_job_error(
         &mut self,
-        _message: DeclareMiningJobError,
+        message: DeclareMiningJobError,
     ) -> Result<SendTo, Error> {
+        let error_code = ErrorDetails::borrowed(message.error_code.inner_as_ref());
+        let error_details = ErrorDetails::borrowed(message.error_details.inner_as_ref());
+        error!(
+            request_id = message.request_id,
+            error_code = %error_code,
+            error_details = %error_details,
+            "DeclareMiningJobError received"
+        );
         // TODO consider using declarative names instead of setting states
         super::super::IS_CUSTOM_JOB_SET.store(true, std::sync::atomic::Ordering::Release);
         Ok(SendTo::None(None))
@@ -41,10 +50,11 @@ impl ParseServerJobDeclarationMessages for JobDeclarator {
         &mut self,
         message: ProvideMissingTransactions,
     ) -> Result<SendTo, Error> {
+        let request_id = message.request_id;
         let tx_list = self
             .last_declare_mining_jobs_sent
-            .get(&message.request_id)
-            .ok_or(Error::UnknownRequestId(message.request_id))?
+            .get(&request_id)
+            .ok_or(Error::UnknownRequestId(request_id))?
             .clone()
             .ok_or(Error::JDSMissingTransactions)?
             .tx_list
@@ -55,7 +65,13 @@ impl ParseServerJobDeclarationMessages for JobDeclarator {
             .iter()
             .filter_map(|&pos| tx_list.get(pos as usize).cloned())
             .collect();
-        let request_id = message.request_id;
+
+        debug!(
+            request_id,
+            requested_txs = unknown_tx_position_list.len(),
+            "Sending ProvideMissingTransactionsSuccess"
+        );
+
         let transaction_list = binary_sv2::Seq064K::new(missing_transactions)
             .map_err(|_| Error::JDSMissingTransactions)?;
         let message_provide_missing_transactions = ProvideMissingTransactionsSuccess {

src/jd_client/job_declarator/mod.rs

@@ -13,12 +13,14 @@ use roles_logic_sv2::{
     utils::Mutex,
 };
 use std::{
+    borrow::Cow,
     collections::{HashMap, HashSet},
     convert::TryInto,
+    fmt,
 };
 use task_manager::TaskManager;
 use tokio::sync::mpsc::{Receiver as TReceiver, Sender as TSender};
-use tracing::{error, info, warn};
+use tracing::{debug, error, info, warn};
 
 use async_recursion::async_recursion;
 use nohash_hasher::BuildNoHashHasher;
@@ -246,10 +248,11 @@ impl JobDeclarator {
             .map_err(|_| Error::JobDeclaratorMutexCorrupted)?;
 
         let template_transactions = tx_list_.to_vec();
+        let tx_count = template_transactions.len();
         let prioritized_txids = crate::prioritized_transactions::snapshot_txids();
         let mut template_txids = HashSet::with_capacity(template_transactions.len());
-        let mut tx_list: Vec<Transaction> = Vec::new();
-        let mut tx_ids = vec![];
+        let mut tx_list: Vec<Transaction> = Vec::with_capacity(tx_count);
+        let mut tx_ids = Vec::with_capacity(tx_count);
         for tx in template_transactions {
             let transaction: Result<Transaction, bitcoin::consensus::encode::Error> =
                 bitcoin::consensus::deserialize(&tx);
@@ -266,6 +269,11 @@ impl JobDeclarator {
                 }
             }
         }
+        debug!(
+            template_id = template.template_id,
+            tx_count,
+            "Received template transaction list"
+        );
         let missing_txids = missing_prioritized_txids(&prioritized_txids, &template_txids);
         if !missing_txids.is_empty() {
             tokio::task::spawn(check_missing_prioritized_txids(
@@ -417,7 +425,14 @@ impl JobDeclarator {
                         }
                     }
                     Ok(SendTo::None(Some(JobDeclaration::DeclareMiningJobError(m)))) => {
-                        error!("Job is not verified: {:?}", m);
+                        let error_code = ErrorDetails::owned(m.error_code.to_vec());
+                        let error_details = ErrorDetails::borrowed(m.error_details.inner_as_ref());
+                        error!(
+                            request_id = m.request_id,
+                            error_code = %error_code,
+                            error_details = %error_details,
+                            "Job is not verified"
+                        );
                     }
                     Ok(SendTo::None(None)) => (),
                     Ok(SendTo::Respond(m)) => {
@@ -647,6 +662,33 @@ async fn check_missing_prioritized_txids(missing_txids: Vec<Txid>, template_id:
     }
 }
 
+struct ErrorDetails<'a>(Cow<'a, [u8]>);
+
+impl<'a> ErrorDetails<'a> {
+    fn borrowed(bytes: &'a [u8]) -> Self {
+        Self(Cow::Borrowed(bytes))
+    }
+
+    fn owned(bytes: Vec<u8>) -> Self {
+        Self(Cow::Owned(bytes))
+    }
+}
+
+impl<'a> fmt::Display for ErrorDetails<'a> {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match std::str::from_utf8(self.0.as_ref()) {
+            Ok(text) => f.write_str(text),
+            Err(_) => {
+                f.write_str("0x")?;
+                for byte in self.0.as_ref() {
+                    write!(f, "{:02x}", byte)?;
+                }
+                Ok(())
+            }
+        }
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use super::missing_prioritized_txids;