From 6ae709e63a1c542c1e02640b0fa85cb0a92ebcd7 Mon Sep 17 00:00:00 2001
From: Floris Bruynooghe <flub@n0.computer>
Date: Tue, 4 Apr 2023 16:59:29 +0200
Subject: [PATCH] feat(loging): Improve logging output of provider and get
 (#932)

This makes the logging output a lot better, driven by real-life
debugging.  It introduces a few more spans and downgrades the
per-frame stuff to trace.
---
 src/get.rs          | 61 ++++++++++++++++++++++++++++-----------------
 src/lib.rs          |  1 +
 src/provider/mod.rs | 15 +++++------
 3 files changed, 47 insertions(+), 30 deletions(-)

diff --git a/src/get.rs b/src/get.rs
index c7a9afe3f6..6a21f606e6 100644
--- a/src/get.rs
+++ b/src/get.rs
@@ -25,7 +25,8 @@ use futures::{Future, StreamExt};
 use postcard::experimental::max_size::MaxSize;
 use range_collections::RangeSet2;
 use tokio::io::{AsyncRead, AsyncReadExt, ReadBuf};
-use tracing::{debug, error};
+use tracing::{debug, debug_span, error};
+use tracing_futures::Instrument;
 
 pub use crate::util::Hash;
 
@@ -153,17 +154,24 @@ where
     C: FnMut(Hash, DataStream, String) -> FutC,
     FutC: Future<Output = Result<DataStream>>,
 {
-    let start = Instant::now();
-    let connection = dial_ticket(ticket, keylog, max_concurrent.into()).await?;
-    run_connection(
-        connection,
-        ticket.hash(),
-        ticket.token(),
-        start,
-        on_connected,
-        on_collection,
-        on_blob,
-    )
+    let span = debug_span!("get", hash=%ticket.hash());
+    async move {
+        let start = Instant::now();
+        let connection = dial_ticket(ticket, keylog, max_concurrent.into()).await?;
+        let span = debug_span!("connection", remote_addr=%connection.remote_address());
+        run_connection(
+            connection,
+            ticket.hash(),
+            ticket.token(),
+            start,
+            on_connected,
+            on_collection,
+            on_blob,
+        )
+        .instrument(span)
+        .await
+    }
+    .instrument(span)
     .await
 }
 
@@ -238,17 +246,24 @@ where
     C: FnMut(Hash, DataStream, String) -> FutC,
     FutC: Future<Output = Result<DataStream>>,
 {
-    let now = Instant::now();
-    let connection = dial_peer(opts).await?;
-    run_connection(
-        connection,
-        hash,
-        auth_token,
-        now,
-        on_connected,
-        on_collection,
-        on_blob,
-    )
+    let span = debug_span!("get", %hash);
+    async move {
+        let now = Instant::now();
+        let connection = dial_peer(opts).await?;
+        let span = debug_span!("connection", remote_addr=%connection.remote_address());
+        run_connection(
+            connection,
+            hash,
+            auth_token,
+            now,
+            on_connected,
+            on_collection,
+            on_blob,
+        )
+        .instrument(span)
+        .await
+    }
+    .instrument(span)
     .await
 }
 
diff --git a/src/lib.rs b/src/lib.rs
index 16ae8581cf..17d50a17b4 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -67,6 +67,7 @@ mod tests {
 
     #[tokio::test]
     async fn many_files() -> Result<()> {
+        setup_logging();
         let num_files = [10, 100, 1000, 10000];
         for num in num_files {
             println!("NUM_FILES: {num}");
diff --git a/src/provider/mod.rs b/src/provider/mod.rs
index 4246a6d175..0a4ef706ab 100644
--- a/src/provider/mod.rs
+++ b/src/provider/mod.rs
@@ -32,7 +32,7 @@ use tokio::io::{AsyncRead, AsyncWrite};
 use tokio::sync::{broadcast, mpsc};
 use tokio::task::JoinError;
 use tokio_util::sync::CancellationToken;
-use tracing::{debug, debug_span, warn};
+use tracing::{debug, debug_span, trace, trace_span, warn};
 use tracing_futures::Instrument;
 use walkdir::WalkDir;
 
@@ -749,7 +749,7 @@ async fn transfer_collection(
 
     writer.write_all(&encoded).await?;
     for (i, blob) in c.blobs().iter().enumerate() {
-        debug!("writing blob {}/{}", i, c.blobs().len());
+        trace!("writing blob {}/{}", i, c.blobs().len());
         tokio::task::yield_now().await;
         let (status, writer1, size) = send_blob(db.clone(), blob.hash, writer, buffer).await?;
         writer = writer1;
@@ -810,7 +810,7 @@ async fn handle_stream(
     };
 
     let hash = request.name;
-    debug!("got request for ({hash})");
+    debug!(%hash, "received request");
     let _ = events.send(Event::RequestReceived {
         connection_id,
         hash,
@@ -822,7 +822,7 @@ async fn handle_stream(
         // We only respond to requests for collections, not individual blobs
         Some(BlobOrCollection::Collection { outboard, data }) => (outboard, data),
         _ => {
-            debug!("not found {}", hash);
+            debug!("not found");
             notify_transfer_aborted(events, connection_id, request_id);
             write_response(&mut writer, &mut out_buffer, Res::NotFound).await?;
             writer.finish().await?;
@@ -975,7 +975,8 @@ fn compute_outboard(
         "can only transfer blob data: {}",
         path.display()
     );
-    tracing::debug!("computing outboard for {}", path.display());
+    let span = trace_span!("outboard.compute", path = %path.display());
+    let _guard = span.enter();
     let file = std::fs::File::open(&path)?;
     // compute outboard size so we can pre-allocate the buffer.
     //
@@ -1001,7 +1002,7 @@ fn compute_outboard(
     let hash =
         bao_tree::io::sync::outboard_post_order(&mut reader, size, IROH_BLOCK_SIZE, &mut outboard)?;
     let ob = PostOrderMemOutboard::load(hash, Cursor::new(&outboard), IROH_BLOCK_SIZE)?.flip();
-    tracing::debug!("done. hash for {} is {hash}", path.display());
+    trace!(%hash, "done");
 
     Ok((hash.into(), ob.into_inner()))
 }
@@ -1133,7 +1134,7 @@ async fn write_response<W: AsyncWrite + Unpin>(
 
     write_lp(&mut writer, used).await?;
 
-    debug!("written response of length {}", used.len());
+    trace!(len = used.len(), "wrote response message frame");
     Ok(())
 }