feat(logging): Add logging with node index and node id for requests; log backoffs

Signed-off-by: Joshua Potts <[email protected]>

Author: iamjpotts

src/execute.rs

@@ -18,6 +18,8 @@
  * ‍
  */
 
+use std::any::type_name;
+use std::borrow::Cow;
 use std::error::Error as StdError;
 use std::ops::ControlFlow;
 use std::time::{
@@ -267,6 +269,23 @@ where
             while let Some(node_index) = random_node_indexes.next().await {
                 let tmp = execute_single(ctx, executable, node_index, &mut transaction_id).await;
 
+                log::log!(
+                    match &tmp {
+                        Ok(ControlFlow::Break(_)) => log::Level::Debug,
+                        Ok(ControlFlow::Continue(_)) => log::Level::Warn,
+                        Err(_) => log::Level::Error,
+                    },
+                    "Execution of {} on node at index {node_index} / node id {} {}",
+                    type_name::<E>(),
+                    ctx.network.channel(node_index).0,
+                    match &tmp {
+                        Ok(ControlFlow::Break(_)) => Cow::Borrowed("succeeded"),
+                        Ok(ControlFlow::Continue(err)) =>
+                            format!("will continue due to {err:?}").into(),
+                        Err(err) => format!("failed due to {err:?}").into(),
+                    },
+                );
+
                 match tmp? {
                     ControlFlow::Continue(err) => last_error = Some(err),
                     ControlFlow::Break(res) => return Ok(res),
@@ -355,6 +374,11 @@ async fn execute_single<E: Execute + Sync>(
 ) -> retry::Result<ControlFlow<E::Response, Error>> {
     let (node_account_id, channel) = ctx.network.channel(node_index);
 
+    log::debug!(
+        "Executing {} on node at index {node_index} / node id {node_account_id}",
+        type_name::<E>()
+    );
+
     let (request, context) = executable
         .make_request(transaction_id.as_ref(), node_account_id)
         .map_err(crate::retry::Error::Permanent)?;

src/retry.rs

@@ -1,6 +1,7 @@
 use futures_core::Future;
 use tokio::time::sleep;
 
+#[derive(Debug)]
 pub(crate) enum Error {
     /// An error that may be resolved after backoff is applied (connection issues for example)
     Transient(crate::Error),
@@ -39,7 +40,13 @@ where
         }
 
         if let Some(duration) = backoff.next_backoff() {
+            let duration_ms = duration.as_millis();
+            let err_suffix =
+                last_error.as_ref().map(|l| format!(" due to {l:?}")).unwrap_or_default();
+
+            log::warn!("Backing off for {duration_ms}ms after failure of attempt {attempt_number}{err_suffix}");
             sleep(duration).await;
+            log::warn!("Backed off for {duration_ms}ms after failure of attempt {attempt_number}{err_suffix}");
         } else {
             let last_error = last_error.expect("timeout while network had no healthy nodes");
             return Err(crate::Error::TimedOut(last_error.into()));