Merge #1508: Add logs for torrent cleaning process

f11dfcc feat: [#1502] adding logs for debugging (Jose Celano)
57b4822 refactor: remove debug print (Jose Celano)

Pull request description:

  This adds more logs to the torrent's cleanup process. It would be helpful to find the bug described in the issue #1502. However, it will be useful afterwards.

  Sample output:

  ```output
  2025-05-08T10:01:18.417631Z  INFO torrust_tracker_lib::bootstrap::jobs::torrent_cleanup: Cleaning up torrents (executed every 60 secs) ...
  2025-05-08T10:01:18.417661Z  INFO bittorrent_tracker_core::torrent::manager: torrents=1 downloads=2 seeders=2 leechers=0
  2025-05-08T10:01:18.417666Z  INFO bittorrent_tracker_core::torrent::manager: peerless_torrents=0 peers=2
  2025-05-08T10:01:18.417670Z  INFO torrust_tracker_torrent_repository::swarms: Removing inactive peers since: 2025-05-08T10:00:48.417669546Z ...
  2025-05-08T10:01:18.417676Z  INFO torrust_tracker_torrent_repository::swarms: Inactive peers removed: 2
  2025-05-08T10:01:18.417679Z  INFO bittorrent_tracker_core::torrent::manager: torrents=1 downloads=2 seeders=0 leechers=0
  2025-05-08T10:01:18.417682Z  INFO bittorrent_tracker_core::torrent::manager: peerless_torrents=1 peers=0
  2025-05-08T10:01:18.417685Z  INFO torrust_tracker_torrent_repository::swarms: Removing peerless torrents ...
  2025-05-08T10:01:18.417688Z  INFO torrust_tracker_torrent_repository::swarms: Peerless torrents removed: 0
  2025-05-08T10:01:18.417690Z  INFO bittorrent_tracker_core::torrent::manager: torrents=1 downloads=2 seeders=0 leechers=0
  2025-05-08T10:01:18.417693Z  INFO bittorrent_tracker_core::torrent::manager: peerless_torrents=1 peers=0
  2025-05-08T10:01:18.417697Z  INFO torrust_tracker_lib::bootstrap::jobs::torrent_cleanup: Cleaned up torrents in: 0 ms
  ```

ACKs for top commit:
  josecelano:
    ACK f11dfcc

Tree-SHA512: 3afdc519b17b3f9fc9792e0d7842d06aba3db32e1fa9a13885f3ef58f0f0f2ff8354aeccf790fbc98142f3d6359dac30983d885bd53341737f472d5989a66902

Author: josecelano

Cargo.lock

@@ -24,6 +24,7 @@ tokio = { version = "1", features = ["macros", "net", "rt-multi-thread", "signal
 torrust-tracker-clock = { version = "3.0.0-develop", path = "../clock" }
 torrust-tracker-configuration = { version = "3.0.0-develop", path = "../configuration" }
 torrust-tracker-primitives = { version = "3.0.0-develop", path = "../primitives" }
+tracing = "0"
 
 [dev-dependencies]
 async-std = { version = "1", features = ["attributes", "tokio1"] }

packages/torrent-repository/Cargo.toml

@@ -101,7 +101,9 @@ impl Swarm {
         }
     }
 
-    pub fn remove_inactive(&mut self, current_cutoff: DurationSinceUnixEpoch) {
+    pub fn remove_inactive(&mut self, current_cutoff: DurationSinceUnixEpoch) -> u64 {
+        let mut inactive_peers_removed = 0;
+
         self.peers.retain(|_, peer| {
             let is_active = peer::ReadInfo::get_updated(peer) > current_cutoff;
 
@@ -112,10 +114,14 @@ impl Swarm {
                 } else {
                     self.metadata.incomplete -= 1;
                 }
+
+                inactive_peers_removed += 1;
             }
 
             is_active
         });
+
+        inactive_peers_removed
     }
 
     #[must_use]
@@ -190,6 +196,11 @@ impl Swarm {
         self.peers.is_empty()
     }
 
+    #[must_use]
+    pub fn is_peerless(&self) -> bool {
+        self.is_empty()
+    }
+
     /// Returns true if the swarm meets the retention policy, meaning that
     /// it should be kept in the list of swarms.
     #[must_use]

packages/torrent-repository/src/swarm.rs

@@ -2,6 +2,7 @@ use std::sync::{Arc, Mutex};
 
 use bittorrent_primitives::info_hash::InfoHash;
 use crossbeam_skiplist::SkipMap;
+use torrust_tracker_clock::conv::convert_from_timestamp_to_datetime_utc;
 use torrust_tracker_configuration::TrackerPolicy;
 use torrust_tracker_primitives::pagination::Pagination;
 use torrust_tracker_primitives::swarm_metadata::{AggregateSwarmMetadata, SwarmMetadata};
@@ -76,24 +77,6 @@ impl Swarms {
         self.swarms.remove(key).map(|entry| entry.value().clone())
     }
 
-    /// Removes inactive peers from all torrent entries.
-    ///
-    /// A peer is considered inactive if its last update timestamp is older than
-    /// the provided cutoff time.
-    ///
-    /// # Errors
-    ///
-    /// This function returns an error if it fails to acquire the lock for any
-    /// swarm handle.
-    pub fn remove_inactive_peers(&self, current_cutoff: DurationSinceUnixEpoch) -> Result<(), Error> {
-        for swarm_handle in &self.swarms {
-            let mut swarm = swarm_handle.value().lock()?;
-            swarm.remove_inactive(current_cutoff);
-        }
-
-        Ok(())
-    }
-
     /// Retrieves a tracked torrent handle by its infohash.
     ///
     /// # Returns
@@ -225,6 +208,34 @@ impl Swarms {
         }
     }
 
+    /// Removes inactive peers from all torrent entries.
+    ///
+    /// A peer is considered inactive if its last update timestamp is older than
+    /// the provided cutoff time.
+    ///
+    /// # Errors
+    ///
+    /// This function returns an error if it fails to acquire the lock for any
+    /// swarm handle.
+    pub fn remove_inactive_peers(&self, current_cutoff: DurationSinceUnixEpoch) -> Result<u64, Error> {
+        tracing::info!(
+            "Removing inactive peers since: {:?} ...",
+            convert_from_timestamp_to_datetime_utc(current_cutoff)
+        );
+
+        let mut inactive_peers_removed = 0;
+
+        for swarm_handle in &self.swarms {
+            let mut swarm = swarm_handle.value().lock()?;
+            let removed = swarm.remove_inactive(current_cutoff);
+            inactive_peers_removed += removed;
+        }
+
+        tracing::info!("Inactive peers removed: {inactive_peers_removed}");
+
+        Ok(inactive_peers_removed)
+    }
+
     /// Removes torrent entries that have no active peers.
     ///
     /// Depending on the tracker policy, torrents without any peers may be
@@ -234,7 +245,11 @@ impl Swarms {
     ///
     /// This function returns an error if it fails to acquire the lock for any
     /// swarm handle.
-    pub fn remove_peerless_torrents(&self, policy: &TrackerPolicy) -> Result<(), Error> {
+    pub fn remove_peerless_torrents(&self, policy: &TrackerPolicy) -> Result<u64, Error> {
+        tracing::info!("Removing peerless torrents ...");
+
+        let mut peerless_torrents_removed = 0;
+
         for swarm_handle in &self.swarms {
             let swarm = swarm_handle.value().lock()?;
 
@@ -243,17 +258,25 @@ impl Swarms {
             }
 
             swarm_handle.remove();
+
+            peerless_torrents_removed += 1;
         }
 
-        Ok(())
+        tracing::info!("Peerless torrents removed: {peerless_torrents_removed}");
+
+        Ok(peerless_torrents_removed)
     }
 
     /// Imports persistent torrent data into the in-memory repository.
     ///
     /// This method takes a set of persisted torrent entries (e.g., from a
     /// database) and imports them into the in-memory repository for immediate
     /// access.
-    pub fn import_persistent(&self, persistent_torrents: &PersistentTorrents) {
+    pub fn import_persistent(&self, persistent_torrents: &PersistentTorrents) -> u64 {
+        tracing::info!("Importing persisted info about torrents ...");
+
+        let mut torrents_imported = 0;
+
         for (info_hash, completed) in persistent_torrents {
             if self.swarms.contains_key(info_hash) {
                 continue;
@@ -264,7 +287,13 @@ impl Swarms {
             // Since SkipMap is lock-free the torrent could have been inserted
             // after checking if it exists.
             self.swarms.get_or_insert(*info_hash, entry);
+
+            torrents_imported += 1;
         }
+
+        tracing::info!("Imported torrents: {torrents_imported}");
+
+        torrents_imported
     }
 
     /// Calculates and returns overall torrent metrics.
@@ -284,9 +313,11 @@ impl Swarms {
     pub fn get_aggregate_swarm_metadata(&self) -> Result<AggregateSwarmMetadata, Error> {
         let mut metrics = AggregateSwarmMetadata::default();
 
-        for entry in &self.swarms {
-            let swarm = entry.value().lock()?;
+        for swarm_handle in &self.swarms {
+            let swarm = swarm_handle.value().lock()?;
+
             let stats = swarm.metadata();
+
             metrics.total_complete += u64::from(stats.complete);
             metrics.total_downloaded += u64::from(stats.downloaded);
             metrics.total_incomplete += u64::from(stats.incomplete);
@@ -296,6 +327,53 @@ impl Swarms {
         Ok(metrics)
     }
 
+    /// Counts the number of torrents that are peerless (i.e., have no active
+    /// peers).
+    ///
+    /// # Returns
+    ///
+    /// A `usize` representing the number of peerless torrents.
+    ///
+    /// # Errors
+    ///
+    /// This function returns an error if it fails to acquire the lock for any
+    /// swarm handle.
+    pub fn count_peerless_torrents(&self) -> Result<usize, Error> {
+        let mut peerless_torrents = 0;
+
+        for swarm_handle in &self.swarms {
+            let swarm = swarm_handle.value().lock()?;
+
+            if swarm.is_peerless() {
+                peerless_torrents += 1;
+            }
+        }
+
+        Ok(peerless_torrents)
+    }
+
+    /// Counts the total number of peers across all torrents.
+    ///
+    /// # Returns
+    ///
+    /// A `usize` representing the total number of peers.
+    ///
+    /// # Errors
+    ///
+    /// This function returns an error if it fails to acquire the lock for any
+    /// swarm handle.
+    pub fn count_peers(&self) -> Result<usize, Error> {
+        let mut peers = 0;
+
+        for swarm_handle in &self.swarms {
+            let swarm = swarm_handle.value().lock()?;
+
+            peers += swarm.len();
+        }
+
+        Ok(peers)
+    }
+
     #[must_use]
     pub fn len(&self) -> usize {
         self.swarms.len()

packages/torrent-repository/src/swarms.rs

@@ -92,16 +92,51 @@ impl TorrentsManager {
     ///    (`remove_peerless_torrents` is set), it removes entire torrent
     ///    entries that have no active peers.
     pub fn cleanup_torrents(&self) {
+        self.log_aggregate_swarm_metadata();
+
+        self.remove_inactive_peers();
+
+        self.log_aggregate_swarm_metadata();
+
+        self.remove_peerless_torrents();
+
+        self.log_aggregate_swarm_metadata();
+    }
+
+    fn remove_inactive_peers(&self) {
         let current_cutoff = CurrentClock::now_sub(&Duration::from_secs(u64::from(self.config.tracker_policy.max_peer_timeout)))
             .unwrap_or_default();
 
         self.in_memory_torrent_repository.remove_inactive_peers(current_cutoff);
+    }
 
+    fn remove_peerless_torrents(&self) {
         if self.config.tracker_policy.remove_peerless_torrents {
             self.in_memory_torrent_repository
                 .remove_peerless_torrents(&self.config.tracker_policy);
         }
     }
+
+    fn log_aggregate_swarm_metadata(&self) {
+        // Pre-calculated data
+        let aggregate_swarm_metadata = self.in_memory_torrent_repository.get_aggregate_swarm_metadata();
+
+        tracing::info!(name: "pre_calculated_aggregate_swarm_metadata",
+            torrents = aggregate_swarm_metadata.total_torrents,
+            downloads = aggregate_swarm_metadata.total_downloaded,
+            seeders = aggregate_swarm_metadata.total_complete,
+            leechers = aggregate_swarm_metadata.total_incomplete,
+        );
+
+        // Hot data (iterating over data structures)
+        let peerless_torrents = self.in_memory_torrent_repository.count_peerless_torrents();
+        let peers = self.in_memory_torrent_repository.count_peers();
+
+        tracing::info!(name: "hot_aggregate_swarm_metadata",
+            peerless_torrents = peerless_torrents,
+            peers = peers,
+        );
+    }
 }
 
 #[cfg(test)]

packages/tracker-core/src/torrent/manager.rs

@@ -241,6 +241,28 @@ impl InMemoryTorrentRepository {
             .expect("Failed to get aggregate swarm metadata")
     }
 
+    /// Counts the number of peerless torrents in the repository.
+    ///
+    /// # Panics
+    ///
+    /// This function panics if the underling swarms return an error.
+    #[must_use]
+    pub fn count_peerless_torrents(&self) -> usize {
+        self.swarms
+            .count_peerless_torrents()
+            .expect("Failed to count peerless torrents")
+    }
+
+    /// Counts the number of peers in the repository.
+    ///
+    /// # Panics
+    ///
+    /// This function panics if the underling swarms return an error.
+    #[must_use]
+    pub fn count_peers(&self) -> usize {
+        self.swarms.count_peers().expect("Failed to count peers")
+    }
+
     /// Imports persistent torrent data into the in-memory repository.
     ///
     /// This method takes a set of persisted torrent entries (e.g., from a database)

packages/tracker-core/src/torrent/repository/in_memory.rs

@@ -119,8 +119,6 @@ impl AnnounceService {
 
             tracing::debug!(target = crate::UDP_TRACKER_LOG_TARGET, "Sending UdpAnnounce event: {event:?}");
 
-            println!("Sending UdpAnnounce event: {event:?}");
-
             udp_stats_event_sender.send(event).await;
         }
     }

packages/udp-tracker-core/src/services/announce.rs

@@ -7,9 +7,15 @@ schema_version = "2.0.0"
 threshold = "info"
 
 [core]
+#inactive_peer_cleanup_interval = 60
 listed = false
 private = false
 
+#[core.tracker_policy]
+#max_peer_timeout = 30
+#persistent_torrent_completed_stat = true
+#remove_peerless_torrents = true
+
 [[udp_trackers]]
 bind_address = "0.0.0.0:6868"
 tracker_usage_statistics = true

share/default/config/tracker.development.sqlite3.toml

@@ -28,6 +28,7 @@ use tracing::instrument;
 pub fn start_job(config: &Core, torrents_manager: &Arc<TorrentsManager>) -> JoinHandle<()> {
     let weak_torrents_manager = std::sync::Arc::downgrade(torrents_manager);
     let interval = config.inactive_peer_cleanup_interval;
+    let interval_in_secs = interval;
 
     tokio::spawn(async move {
         let interval = std::time::Duration::from_secs(interval);
@@ -43,9 +44,9 @@ pub fn start_job(config: &Core, torrents_manager: &Arc<TorrentsManager>) -> Join
                 _ = interval.tick() => {
                     if let Some(torrents_manager) = weak_torrents_manager.upgrade() {
                         let start_time = Utc::now().time();
-                        tracing::info!("Cleaning up torrents..");
+                        tracing::info!("Cleaning up torrents (executed every {} secs) ...", interval_in_secs);
                         torrents_manager.cleanup_torrents();
-                        tracing::info!("Cleaned up torrents in: {}ms", (Utc::now().time() - start_time).num_milliseconds());
+                        tracing::info!("Cleaned up torrents in: {} ms", (Utc::now().time() - start_time).num_milliseconds());
                     } else {
                         break;
                     }