From b30ee1338881f14bf0d23dc00f0e700ae5219c28 Mon Sep 17 00:00:00 2001
From: Igor Katson <igor.katson@gmail.com>
Date: Mon, 26 Feb 2024 09:42:06 +0000
Subject: [PATCH] Logging for UDP trackers

---
 .../librqbit/src/tracing_subscriber_config_utils.rs |  1 -
 crates/librqbit/src/tracker_comms.rs                |  6 +++++-
 crates/librqbit/src/tracker_comms_udp.rs            | 13 ++++++++++---
 3 files changed, 15 insertions(+), 5 deletions(-)

diff --git a/crates/librqbit/src/tracing_subscriber_config_utils.rs b/crates/librqbit/src/tracing_subscriber_config_utils.rs
index cc595b2..7cac1a2 100644
--- a/crates/librqbit/src/tracing_subscriber_config_utils.rs
+++ b/crates/librqbit/src/tracing_subscriber_config_utils.rs
@@ -96,7 +96,6 @@ pub fn init_logging(opts: InitLoggingOptions) -> anyhow::Result<InitLoggingResul
             std::fs::OpenOptions::new()
                 .create(true)
                 .append(true)
-                .write(true)
                 .open(&log_file)
                 .with_context(|| format!("error opening log file {:?}", log_file))?,
         ));
diff --git a/crates/librqbit/src/tracker_comms.rs b/crates/librqbit/src/tracker_comms.rs
index 61fe467..e5b83ef 100644
--- a/crates/librqbit/src/tracker_comms.rs
+++ b/crates/librqbit/src/tracker_comms.rs
@@ -10,6 +10,7 @@ use tokio_util::sync::CancellationToken;
 use tracing::debug;
 use tracing::error_span;
 use tracing::info;
+use tracing::trace;
 use url::Url;
 
 use crate::tracker_comms_http;
@@ -96,6 +97,7 @@ impl TrackerComms {
         if tracker.starts_with("http://") || tracker.starts_with("https://") {
             spawn_with_cancel(
                 error_span!(
+                    parent: None,
                     "http_tracker",
                     tracker = tracker,
                     info_hash = ?self.info_hash
@@ -109,7 +111,7 @@ impl TrackerComms {
             );
         } else if tracker.starts_with("udp://") {
             spawn_with_cancel(
-                error_span!("udp_tracker", tracker = tracker),
+                error_span!(parent: None, "udp_tracker", tracker = tracker, info_hash = ?self.info_hash),
                 self.cancellation_token.clone(),
                 {
                     let comms = self;
@@ -206,6 +208,7 @@ impl TrackerComms {
         let mut sleep_interval: Option<Duration> = None;
         loop {
             if let Some(i) = sleep_interval {
+                trace!(interval=?sleep_interval, "sleeping");
                 tokio::time::sleep(i).await;
             }
 
@@ -222,6 +225,7 @@ impl TrackerComms {
 
             match requester.announce(request).await {
                 Ok(response) => {
+                    trace!(len = response.addrs.len(), "received announce response");
                     for addr in response.addrs {
                         self.tx
                             .send(SocketAddr::V4(addr))
diff --git a/crates/librqbit/src/tracker_comms_udp.rs b/crates/librqbit/src/tracker_comms_udp.rs
index c32a143..1e72ae8 100644
--- a/crates/librqbit/src/tracker_comms_udp.rs
+++ b/crates/librqbit/src/tracker_comms_udp.rs
@@ -4,6 +4,7 @@ use anyhow::{bail, Context};
 use librqbit_core::hash_id::Id20;
 use rand::Rng;
 use tokio::net::ToSocketAddrs;
+use tracing::trace;
 
 const ACTION_CONNECT: u32 = 0;
 const ACTION_ANNOUNCE: u32 = 1;
@@ -190,6 +191,7 @@ impl UdpTrackerRequester {
         let mut write_buf = Vec::new();
         let mut read_buf = vec![0u8; 4096];
 
+        trace!("sending connect request");
         Request::Connect.serialize(tid, &mut write_buf);
 
         sock.send(&write_buf)
@@ -206,12 +208,15 @@ impl UdpTrackerRequester {
         if tid != rtid {
             bail!("expected transaction id {} == {}", tid, rtid);
         }
+        trace!(response=?response, "received");
 
         let connection_id = match response {
             Response::Connect(connection_id) => connection_id,
             other => bail!("unexpected response {other:?}"),
         };
 
+        trace!(connection_id);
+
         Ok(Self {
             sock,
             connection_id,
@@ -233,7 +238,7 @@ impl UdpTrackerRequester {
         let tid = new_transaction_id();
         self.write_buf.clear();
         let size = request.serialize(tid, &mut self.write_buf);
-
+        trace!(request=?request, tid, "sending");
         self.sock
             .send(&self.write_buf[..size])
             .await
@@ -241,7 +246,10 @@ impl UdpTrackerRequester {
         let size = self.sock.recv(&mut self.read_buf).await.unwrap();
 
         let (rtid, response) = Response::parse(&self.read_buf[..size]).unwrap();
-        assert_eq!(tid, rtid);
+        trace!("received response");
+        if tid != rtid {
+            bail!("unexpected transaction id");
+        }
         Ok(response)
     }
 }
@@ -251,7 +259,6 @@ mod tests {
     use std::{io::Write, str::FromStr};
 
     use librqbit_core::{hash_id::Id20, peer_id::generate_peer_id};
-    pub use rand::Rng;
 
     use crate::tracker_comms_udp::{
         new_transaction_id, AnnounceFields, Request, Response, EVENT_NONE,