Add latency to UDP tracker logs

src/servers/udp/handlers.rs

@@ -3,6 +3,7 @@ use std::fmt;
 use std::net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr};
 use std::panic::Location;
 use std::sync::Arc;
+use std::time::Instant;
 
 use aquatic_udp_protocol::{
     AnnounceInterval, AnnounceRequest, AnnounceResponse, ConnectRequest, ConnectResponse, ErrorResponse, NumberOfDownloads,
@@ -35,6 +36,8 @@ use crate::shared::bit_torrent::info_hash::InfoHash;
 pub(crate) async fn handle_packet(udp_request: UdpRequest, tracker: &Arc<Tracker>, socket: Arc<UdpSocket>) -> Response {
     debug!("Handling Packets: {udp_request:?}");
 
+    let start_time = Instant::now();
+
     let request_id = RequestId::make(&udp_request);
     let server_socket_addr = socket.local_addr().expect("Could not get local_addr for socket.");
 
@@ -58,7 +61,9 @@ pub(crate) async fn handle_packet(udp_request: UdpRequest, tracker: &Arc<Tracker
                 Err(e) => handle_error(&e, transaction_id),
             };
 
-            log_response(&response, &transaction_id, &request_id, &server_socket_addr);
+            let latency = start_time.elapsed();
+
+            log_response(&response, &transaction_id, &request_id, &server_socket_addr, latency);
 
             response
         }

src/servers/udp/logging.rs

@@ -1,6 +1,7 @@
 //! Logging for UDP Tracker requests and responses.
 
 use std::net::SocketAddr;
+use std::time::Duration;
 
 use aquatic_udp_protocol::{Request, Response, TransactionId};
 
@@ -36,7 +37,13 @@ pub fn log_request(request: &Request, request_id: &RequestId, server_socket_addr
 
             tracing::span!(
                 target: "UDP TRACKER",
-                tracing::Level::INFO, "request", server_socket_addr = %server_socket_addr, action = %action, transaction_id = %transaction_id_str, request_id = %request_id, connection_id = %connection_id_str);
+                tracing::Level::INFO,
+                "request",
+                server_socket_addr = %server_socket_addr,
+                action = %action,
+                transaction_id = %transaction_id_str,
+                request_id = %request_id,
+                connection_id = %connection_id_str);
         }
     };
 }
@@ -54,10 +61,16 @@ pub fn log_response(
     transaction_id: &TransactionId,
     request_id: &RequestId,
     server_socket_addr: &SocketAddr,
+    latency: Duration,
 ) {
     tracing::span!(
         target: "UDP TRACKER",
-        tracing::Level::INFO, "response", server_socket_addr = %server_socket_addr, transaction_id = %transaction_id.0.to_string(), request_id = %request_id);
+        tracing::Level::INFO, 
+        "response", 
+        server_socket_addr = %server_socket_addr, 
+        transaction_id = %transaction_id.0.to_string(), 
+        request_id = %request_id,
+        latency_ms = %latency.as_millis());
 }
 
 pub fn log_bad_request(request_id: &RequestId) {