diff --git a/src/servers/udp/handlers.rs b/src/servers/udp/handlers.rs index f8424879f..91a371a7b 100644 --- a/src/servers/udp/handlers.rs +++ b/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, socket: Arc) -> 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 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 } diff --git a/src/servers/udp/logging.rs b/src/servers/udp/logging.rs index bd1c2951b..a32afc6a3 100644 --- a/src/servers/udp/logging.rs +++ b/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) {