Merge torrust#1095: udp: improve logging (and vairous changes)

8c70395 udp: various changes (Cameron Garnham)

Pull request description:

  When making this pull request I found that there was logic for the UDP tracker when in private mode: that we do not support, so I removed this dead-code.

  I also found that the `ConnectionId` was not being checked for scrape requests, and when parsing badly formatted requests, so I corrected for this.

  I also added the statistic counting for how many error responses have been sent.

ACKs for top commit:
  josecelano:
    ACK 8c70395

Tree-SHA512: 5047d42932d09b44b387133066e3feba80446e29b26c8ae952d35c4655991376c00b6a21e5975eda53f8e8a460db32c14d54772c78802a7596f70551a5393171

cSpell.json

@@ -164,6 +164,7 @@
         "typenum",
         "Unamed",
         "underflows",
+        "Unsendable",
         "untuple",
         "uroot",
         "Vagaa",

src/core/mod.rs

@@ -470,6 +470,7 @@ use torrust_tracker_primitives::torrent_metrics::TorrentsMetrics;
 use torrust_tracker_primitives::{peer, DurationSinceUnixEpoch};
 use torrust_tracker_torrent_repository::entry::EntrySync;
 use torrust_tracker_torrent_repository::repository::Repository;
+use tracing::instrument;
 
 use self::auth::Key;
 use self::error::Error;
@@ -1092,6 +1093,7 @@ impl Tracker {
     ///
     /// Will return an error if the tracker is running in `listed` mode
     /// and the infohash is not whitelisted.
+    #[instrument(skip(self, info_hash), err)]
     pub async fn authorize(&self, info_hash: &InfoHash) -> Result<(), Error> {
         if !self.is_listed() {
             return Ok(());

src/core/services/statistics/mod.rs

@@ -76,9 +76,11 @@ pub async fn get_metrics(tracker: Arc<Tracker>) -> TrackerMetrics {
             udp4_connections_handled: stats.udp4_connections_handled,
             udp4_announces_handled: stats.udp4_announces_handled,
             udp4_scrapes_handled: stats.udp4_scrapes_handled,
+            udp4_errors_handled: stats.udp4_errors_handled,
             udp6_connections_handled: stats.udp6_connections_handled,
             udp6_announces_handled: stats.udp6_announces_handled,
             udp6_scrapes_handled: stats.udp6_scrapes_handled,
+            udp6_errors_handled: stats.udp6_errors_handled,
         },
     }
 }

src/core/statistics.rs

@@ -47,9 +47,11 @@ pub enum Event {
     Udp4Connect,
     Udp4Announce,
     Udp4Scrape,
+    Udp4Error,
     Udp6Connect,
     Udp6Announce,
     Udp6Scrape,
+    Udp6Error,
 }
 
 /// Metrics collected by the tracker.
@@ -82,12 +84,16 @@ pub struct Metrics {
     pub udp4_announces_handled: u64,
     /// Total number of UDP (UDP tracker) `scrape` requests from IPv4 peers.
     pub udp4_scrapes_handled: u64,
+    /// Total number of UDP (UDP tracker) `error` requests from IPv4 peers.
+    pub udp4_errors_handled: u64,
     /// Total number of UDP (UDP tracker) `connection` requests from IPv6 peers.
     pub udp6_connections_handled: u64,
     /// Total number of UDP (UDP tracker) `announce` requests from IPv6 peers.
     pub udp6_announces_handled: u64,
     /// Total number of UDP (UDP tracker) `scrape` requests from IPv6 peers.
     pub udp6_scrapes_handled: u64,
+    /// Total number of UDP (UDP tracker) `error` requests from IPv6 peers.
+    pub udp6_errors_handled: u64,
 }
 
 /// The service responsible for keeping tracker metrics (listening to statistics events and handle them).
@@ -168,6 +174,9 @@ async fn event_handler(event: Event, stats_repository: &Repo) {
         Event::Udp4Scrape => {
             stats_repository.increase_udp4_scrapes().await;
         }
+        Event::Udp4Error => {
+            stats_repository.increase_udp4_errors().await;
+        }
 
         // UDP6
         Event::Udp6Connect => {
@@ -179,6 +188,9 @@ async fn event_handler(event: Event, stats_repository: &Repo) {
         Event::Udp6Scrape => {
             stats_repository.increase_udp6_scrapes().await;
         }
+        Event::Udp6Error => {
+            stats_repository.increase_udp6_errors().await;
+        }
     }
 
     tracing::debug!("stats: {:?}", stats_repository.get_stats().await);
@@ -282,6 +294,12 @@ impl Repo {
         drop(stats_lock);
     }
 
+    pub async fn increase_udp4_errors(&self) {
+        let mut stats_lock = self.stats.write().await;
+        stats_lock.udp4_errors_handled += 1;
+        drop(stats_lock);
+    }
+
     pub async fn increase_udp6_connections(&self) {
         let mut stats_lock = self.stats.write().await;
         stats_lock.udp6_connections_handled += 1;
@@ -299,6 +317,12 @@ impl Repo {
         stats_lock.udp6_scrapes_handled += 1;
         drop(stats_lock);
     }
+
+    pub async fn increase_udp6_errors(&self) {
+        let mut stats_lock = self.stats.write().await;
+        stats_lock.udp6_errors_handled += 1;
+        drop(stats_lock);
+    }
 }
 
 #[cfg(test)]

src/servers/apis/v1/context/stats/resources.rs

@@ -38,12 +38,16 @@ pub struct Stats {
     pub udp4_announces_handled: u64,
     /// Total number of UDP (UDP tracker) `scrape` requests from IPv4 peers.
     pub udp4_scrapes_handled: u64,
+    /// Total number of UDP (UDP tracker) `scrape` requests from IPv4 peers.
+    pub udp4_errors_handled: u64,
     /// Total number of UDP (UDP tracker) `connection` requests from IPv6 peers.
     pub udp6_connections_handled: u64,
     /// Total number of UDP (UDP tracker) `announce` requests from IPv6 peers.
     pub udp6_announces_handled: u64,
     /// Total number of UDP (UDP tracker) `scrape` requests from IPv6 peers.
     pub udp6_scrapes_handled: u64,
+    /// Total number of UDP (UDP tracker) `scrape` requests from IPv6 peers.
+    pub udp6_errors_handled: u64,
 }
 
 impl From<TrackerMetrics> for Stats {
@@ -62,9 +66,11 @@ impl From<TrackerMetrics> for Stats {
             udp4_connections_handled: metrics.protocol_metrics.udp4_connections_handled,
             udp4_announces_handled: metrics.protocol_metrics.udp4_announces_handled,
             udp4_scrapes_handled: metrics.protocol_metrics.udp4_scrapes_handled,
+            udp4_errors_handled: metrics.protocol_metrics.udp4_errors_handled,
             udp6_connections_handled: metrics.protocol_metrics.udp6_connections_handled,
             udp6_announces_handled: metrics.protocol_metrics.udp6_announces_handled,
             udp6_scrapes_handled: metrics.protocol_metrics.udp6_scrapes_handled,
+            udp6_errors_handled: metrics.protocol_metrics.udp6_errors_handled,
         }
     }
 }
@@ -97,9 +103,11 @@ mod tests {
                     udp4_connections_handled: 11,
                     udp4_announces_handled: 12,
                     udp4_scrapes_handled: 13,
-                    udp6_connections_handled: 14,
-                    udp6_announces_handled: 15,
-                    udp6_scrapes_handled: 16
+                    udp4_errors_handled: 14,
+                    udp6_connections_handled: 15,
+                    udp6_announces_handled: 16,
+                    udp6_scrapes_handled: 17,
+                    udp6_errors_handled: 18
                 }
             }),
             Stats {
@@ -116,9 +124,11 @@ mod tests {
                 udp4_connections_handled: 11,
                 udp4_announces_handled: 12,
                 udp4_scrapes_handled: 13,
-                udp6_connections_handled: 14,
-                udp6_announces_handled: 15,
-                udp6_scrapes_handled: 16
+                udp4_errors_handled: 14,
+                udp6_connections_handled: 15,
+                udp6_announces_handled: 16,
+                udp6_scrapes_handled: 17,
+                udp6_errors_handled: 18
             }
         );
     }

src/servers/udp/connection_cookie.rs

@@ -79,6 +79,7 @@
 
 use aquatic_udp_protocol::ConnectionId as Cookie;
 use cookie_builder::{assemble, decode, disassemble, encode};
+use tracing::instrument;
 use zerocopy::AsBytes;
 
 use super::error::Error;
@@ -94,9 +95,12 @@ use crate::shared::crypto::keys::CipherArrayBlowfish;
 ///
 /// It would panic if the cookie is not exactly 8 bytes is size.
 ///
+#[instrument(err)]
 pub fn make(fingerprint: u64, issue_at: f64) -> Result<Cookie, Error> {
     if !issue_at.is_normal() {
-        return Err(Error::InvalidCookieIssueTime { invalid_value: issue_at });
+        return Err(Error::CookieValueNotNormal {
+            not_normal_value: issue_at,
+        });
     }
 
     let cookie = assemble(fingerprint, issue_at);
@@ -117,6 +121,7 @@ use std::ops::Range;
 /// # Panics
 ///
 /// It would panic if the range start is not smaller than it's end.
+#[instrument(err)]
 pub fn check(cookie: &Cookie, fingerprint: u64, valid_range: Range<f64>) -> Result<f64, Error> {
     assert!(valid_range.start <= valid_range.end, "range start is larger than range end");
 
@@ -126,20 +131,20 @@ pub fn check(cookie: &Cookie, fingerprint: u64, valid_range: Range<f64>) -> Resu
     let issue_time = disassemble(fingerprint, cookie_bytes);
 
     if !issue_time.is_normal() {
-        return Err(Error::ConnectionIdNotNormal {
+        return Err(Error::CookieValueNotNormal {
             not_normal_value: issue_time,
         });
     }
 
     if issue_time < valid_range.start {
-        return Err(Error::ConnectionIdExpired {
+        return Err(Error::CookieValueExpired {
             expired_value: issue_time,
             min_value: valid_range.start,
         });
     }
 
     if issue_time > valid_range.end {
-        return Err(Error::ConnectionIdFromFuture {
+        return Err(Error::CookieValueFromFuture {
             future_value: issue_time,
             max_value: valid_range.end,
         });
@@ -150,15 +155,15 @@ pub fn check(cookie: &Cookie, fingerprint: u64, valid_range: Range<f64>) -> Resu
 
 mod cookie_builder {
     use cipher::{BlockDecrypt, BlockEncrypt};
-    use tracing::{instrument, Level};
+    use tracing::instrument;
     use zerocopy::{byteorder, AsBytes as _, NativeEndian};
 
     pub type CookiePlainText = CipherArrayBlowfish;
     pub type CookieCipherText = CipherArrayBlowfish;
 
     use crate::shared::crypto::keys::{CipherArrayBlowfish, Current, Keeper};
 
-    #[instrument(ret(level = Level::TRACE))]
+    #[instrument()]
     pub(super) fn assemble(fingerprint: u64, issue_at: f64) -> CookiePlainText {
         let issue_at: byteorder::I64<NativeEndian> =
             *zerocopy::FromBytes::ref_from(&issue_at.to_ne_bytes()).expect("it should be aligned");
@@ -172,7 +177,7 @@ mod cookie_builder {
         *CipherArrayBlowfish::from_slice(cookie.as_bytes())
     }
 
-    #[instrument(ret(level = Level::TRACE))]
+    #[instrument()]
     pub(super) fn disassemble(fingerprint: u64, cookie: CookiePlainText) -> f64 {
         let fingerprint: byteorder::I64<NativeEndian> =
             *zerocopy::FromBytes::ref_from(&fingerprint.to_ne_bytes()).expect("it should be aligned");
@@ -189,7 +194,7 @@ mod cookie_builder {
         issue_time.get()
     }
 
-    #[instrument(ret(level = Level::TRACE))]
+    #[instrument()]
     pub(super) fn encode(mut cookie: CookiePlainText) -> CookieCipherText {
         let cipher = Current::get_cipher_blowfish();
 
@@ -198,7 +203,7 @@ mod cookie_builder {
         cookie
     }
 
-    #[instrument(ret(level = Level::TRACE))]
+    #[instrument()]
     pub(super) fn decode(mut cookie: CookieCipherText) -> CookiePlainText {
         let cipher = Current::get_cipher_blowfish();
 
@@ -282,7 +287,7 @@ mod tests {
         let result = check(&cookie, fingerprint, min..max).unwrap_err();
 
         match result {
-            Error::ConnectionIdExpired { .. } => {} // Expected error
+            Error::CookieValueExpired { .. } => {} // Expected error
             _ => panic!("Expected ConnectionIdExpired error"),
         }
     }
@@ -300,7 +305,7 @@ mod tests {
         let result = check(&cookie, fingerprint, min..max).unwrap_err();
 
         match result {
-            Error::ConnectionIdFromFuture { .. } => {} // Expected error
+            Error::CookieValueFromFuture { .. } => {} // Expected error
             _ => panic!("Expected ConnectionIdFromFuture error"),
         }
     }

src/servers/udp/error.rs

@@ -1,7 +1,7 @@
 //! Error types for the UDP server.
 use std::panic::Location;
 
-use aquatic_udp_protocol::ConnectionId;
+use aquatic_udp_protocol::{ConnectionId, RequestParseError};
 use derive_more::derive::Display;
 use thiserror::Error;
 use torrust_tracker_located_error::LocatedError;
@@ -13,17 +13,17 @@ pub struct ConnectionCookie(pub ConnectionId);
 /// Error returned by the UDP server.
 #[derive(Error, Debug)]
 pub enum Error {
-    #[error("the issue time should be a normal floating point number")]
-    InvalidCookieIssueTime { invalid_value: f64 },
+    #[error("cookie value is not normal: {not_normal_value}")]
+    CookieValueNotNormal { not_normal_value: f64 },
 
-    #[error("connection id did not produce a normal value")]
-    ConnectionIdNotNormal { not_normal_value: f64 },
+    #[error("cookie value is expired: {expired_value}, expected > {min_value}")]
+    CookieValueExpired { expired_value: f64, min_value: f64 },
 
-    #[error("connection id produced an expired value")]
-    ConnectionIdExpired { expired_value: f64, min_value: f64 },
+    #[error("cookie value is from future: {future_value}, expected < {max_value}")]
+    CookieValueFromFuture { future_value: f64, max_value: f64 },
 
-    #[error("connection id produces a future value")]
-    ConnectionIdFromFuture { future_value: f64, max_value: f64 },
+    #[error("error when phrasing request: {request_parse_error:?}")]
+    RequestParseError { request_parse_error: RequestParseError },
 
     /// Error returned when the domain tracker returns an error.
     #[error("tracker server error: {source}")]
@@ -48,3 +48,9 @@ pub enum Error {
     #[error("domain tracker requires authentication but is not supported in current UDP implementation. Location: {location}")]
     TrackerAuthenticationRequired { location: &'static Location<'static> },
 }
+
+impl From<RequestParseError> for Error {
+    fn from(request_parse_error: RequestParseError) -> Self {
+        Self::RequestParseError { request_parse_error }
+    }
+}