fetch: add logging for stages

Log when different stages of the fetch have completed, while also
providing the elapsed time, in seconds.

Signed-off-by: Fintan Halpenny <fintan.halpenny@gmail.com>
X-Clacks-Overhead: GNU Terry Pratchett

radicle-fetch/src/lib.rs

@@ -11,10 +11,12 @@ mod state;
 
 pub use handle::Handle;
 pub use policy::{Allowed, BlockList, Scope};
+use radicle::storage::ReadRepository as _;
 pub use state::{FetchLimit, FetchResult};
 pub use transport::Transport;
 
 use std::io;
+use std::time::Instant;
 
 use radicle::crypto::PublicKey;
 use radicle::storage::refs::RefsAt;
@@ -55,6 +57,7 @@ pub fn pull<S>(
 where
     S: transport::ConnectionStream,
 {
+    let start = Instant::now();
     let local = *handle.local();
     if local == remote {
         return Err(Error::ReplicateSelf);
@@ -67,9 +70,17 @@ where
 
     // N.b. ensure that we ignore the local peer's key.
     handle.blocked.extend([local]);
-    state
+    let result = state
         .run(handle, &handshake, limit, remote, refs_at)
-        .map_err(Error::Protocol)
+        .map_err(Error::Protocol);
+
+    log::debug!(
+        target: "fetch",
+        "Finished pull of {} ({}ms)",
+        handle.repo.id(),
+        start.elapsed().as_millis()
+    );
+    result
 }
 
 /// Clone changes from the `remote`.
@@ -84,6 +95,7 @@ pub fn clone<S>(
 where
     S: transport::ConnectionStream,
 {
+    let start = Instant::now();
     if *handle.local() == remote {
         return Err(Error::ReplicateSelf);
     }
@@ -92,7 +104,15 @@ where
         .handshake()
         .map_err(|err| Error::Handshake { err })?;
     let state = FetchState::default();
-    state
+    let result = state
         .run(handle, &handshake, limit, remote, None)
-        .map_err(Error::Protocol)
+        .map_err(Error::Protocol);
+
+    log::debug!(
+        target: "fetch",
+        "Finished clone of {} ({}ms)",
+        handle.repo.id(),
+        start.elapsed().as_millis(),
+    );
+    result
 }

radicle-fetch/src/state.rs

@@ -1,4 +1,5 @@
 use std::collections::{BTreeMap, BTreeSet};
+use std::time::Instant;
 
 use gix_protocol::handshake;
 use radicle::crypto::PublicKey;
@@ -378,6 +379,7 @@ impl FetchState {
     where
         S: transport::ConnectionStream,
     {
+        let start = Instant::now();
         // N.b. we always fetch the `rad/id` since our delegate set
         // might be further ahead than theirs, e.g. we are the
         // deciding vote on adding a delegate.
@@ -389,6 +391,7 @@ impl FetchState {
                 limit: limit.special,
             },
         )?;
+        log::debug!(target: "fetch", "Fetched rad/id ({}ms)", start.elapsed().as_millis());
 
         // N.b. The error case here should not happen. In the case of
         // a `clone` we have asked for refs/rad/id and ensured it was
@@ -418,6 +421,12 @@ impl FetchState {
             remote,
             refs_at,
         )?;
+        log::debug!(
+            target: "fetch",
+            "Fetched rad/sigrefs for {} remotes ({}ms)",
+            signed_refs.len(),
+            start.elapsed().as_millis()
+        );
 
         let data_refs = stage::DataRefs {
             remote,
@@ -425,6 +434,12 @@ impl FetchState {
             limit: limit.refs,
         };
         self.run_stage(handle, handshake, &data_refs)?;
+        log::debug!(
+            target: "fetch",
+            "Fetched data refs for {} remotes ({}ms)",
+            data_refs.remotes.len(),
+            start.elapsed().as_millis()
+        );
 
         // Run validation of signed refs, pruning any offending
         // remotes from the tips, thus not updating the production Git
@@ -528,10 +543,16 @@ impl FetchState {
                 }
             }
         }
-
         // N.b. signal to exit the upload-pack sequence
         handle.transport.done()?;
 
+        log::debug!(
+            target: "fetch",
+            "Validated {} remotes ({}ms)",
+            remotes.len(),
+            start.elapsed().as_millis()
+        );
+
         // N.b. only apply to Git repository if no delegates have failed verification.
         if failures.is_empty() {
             let applied = repository::update(
@@ -541,12 +562,20 @@ impl FetchState {
                     .into_values()
                     .flat_map(|ups| ups.into_iter()),
             )?;
+            log::debug!(target: "fetch", "Applied updates ({}ms)", start.elapsed().as_millis());
             Ok(FetchResult::Success {
                 applied,
                 remotes,
                 warnings,
             })
         } else {
+            log::debug!(
+                target: "fetch",
+                "Fetch failed: {} warning(s) and {} failure(s) ({}ms)",
+                warnings.len(),
+                failures.len(),
+                start.elapsed().as_millis()
+            );
             Ok(FetchResult::Failed { warnings, failures })
         }
     }