From 33e72bb04e14370e90ec1c421b3666488e72e19a Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Thu, 26 Dec 2024 15:46:43 +0000 Subject: [PATCH 1/3] tests: add info-hash to announce req fixture --- tests/servers/udp/contract.rs | 36 +++++++++++++++++++++++++++-------- 1 file changed, 28 insertions(+), 8 deletions(-) diff --git a/tests/servers/udp/contract.rs b/tests/servers/udp/contract.rs index 86bb1d18c..ddccf4f9a 100644 --- a/tests/servers/udp/contract.rs +++ b/tests/servers/udp/contract.rs @@ -118,22 +118,30 @@ mod receiving_an_announce_request { use torrust_tracker_configuration::DEFAULT_TIMEOUT; use torrust_tracker_test_helpers::configuration; + use crate::common::fixtures::random_info_hash; use crate::common::logging; use crate::servers::udp::asserts::is_ipv4_announce_response; use crate::servers::udp::contract::send_connection_request; use crate::servers::udp::Started; - pub async fn assert_send_and_get_announce(tx_id: TransactionId, c_id: ConnectionId, client: &UdpTrackerClient) { - let response = send_and_get_announce(tx_id, c_id, client).await; + pub async fn assert_send_and_get_announce( + tx_id: TransactionId, + c_id: ConnectionId, + info_hash: bittorrent_primitives::info_hash::InfoHash, + client: &UdpTrackerClient, + ) { + let response = send_and_get_announce(tx_id, c_id, info_hash, client).await; assert!(is_ipv4_announce_response(&response)); } pub async fn send_and_get_announce( tx_id: TransactionId, c_id: ConnectionId, + info_hash: bittorrent_primitives::info_hash::InfoHash, client: &UdpTrackerClient, ) -> aquatic_udp_protocol::Response { - let announce_request = build_sample_announce_request(tx_id, c_id, client.client.socket.local_addr().unwrap().port()); + let announce_request = + build_sample_announce_request(tx_id, c_id, client.client.socket.local_addr().unwrap().port(), info_hash); match client.send(announce_request.into()).await { Ok(_) => (), @@ -146,12 +154,17 @@ mod receiving_an_announce_request { } } - fn build_sample_announce_request(tx_id: TransactionId, c_id: ConnectionId, port: u16) -> AnnounceRequest { + fn build_sample_announce_request( + tx_id: TransactionId, + c_id: ConnectionId, + port: u16, + info_hash: bittorrent_primitives::info_hash::InfoHash, + ) -> AnnounceRequest { AnnounceRequest { connection_id: ConnectionId(c_id.0), action_placeholder: AnnounceActionPlaceholder::default(), transaction_id: tx_id, - info_hash: InfoHash([0u8; 20]), + info_hash: InfoHash(info_hash.0), peer_id: PeerId([255u8; 20]), bytes_downloaded: NumberOfBytes(0i64.into()), bytes_uploaded: NumberOfBytes(0i64.into()), @@ -179,7 +192,9 @@ mod receiving_an_announce_request { let c_id = send_connection_request(tx_id, &client).await; - assert_send_and_get_announce(tx_id, c_id, &client).await; + let info_hash = random_info_hash(); + + assert_send_and_get_announce(tx_id, c_id, info_hash, &client).await; env.stop().await; } @@ -199,9 +214,11 @@ mod receiving_an_announce_request { let c_id = send_connection_request(tx_id, &client).await; + let info_hash = random_info_hash(); + for x in 0..1000 { tracing::info!("req no: {x}"); - assert_send_and_get_announce(tx_id, c_id, &client).await; + assert_send_and_get_announce(tx_id, c_id, info_hash, &client).await; } env.stop().await; @@ -224,9 +241,11 @@ mod receiving_an_announce_request { let invalid_connection_id = ConnectionId::new(0); // Zero is one of the not normal values. + let info_hash = random_info_hash(); + for x in 0..=10 { tracing::info!("req no: {x}"); - send_and_get_announce(tx_id, invalid_connection_id, &client).await; + send_and_get_announce(tx_id, invalid_connection_id, info_hash, &client).await; } // The twelfth request should be banned (timeout error) @@ -235,6 +254,7 @@ mod receiving_an_announce_request { tx_id, invalid_connection_id, client.client.socket.local_addr().unwrap().port(), + info_hash, ); match client.send(announce_request.into()).await { From 5f206f0ad806a93c0878b3a3218a4ef8bc80434a Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Thu, 26 Dec 2024 16:14:02 +0000 Subject: [PATCH 2/3] feat: add more fields to UDP error response log ``` 2024-12-26T16:12:06.336340Z ERROR UDP TRACKER: response error error=cookie value is from future: 6831818432388564000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735229527.33634 remote_addr=127.0.0.1:35550 local_addr=127.0.0.1:36599 request_id=ce34c229-82c6-4a18-a60c-5eea1cf55919 transaction_id=123 ``` Added custom log with fields: - remote_addr - request_id - transaction_id --- src/servers/udp/connection_cookie.rs | 2 +- src/servers/udp/handlers.rs | 33 +++++++++++++++++++++++++--- 2 files changed, 31 insertions(+), 4 deletions(-) diff --git a/src/servers/udp/connection_cookie.rs b/src/servers/udp/connection_cookie.rs index 50359033c..439be9da7 100644 --- a/src/servers/udp/connection_cookie.rs +++ b/src/servers/udp/connection_cookie.rs @@ -121,7 +121,7 @@ use std::ops::Range; /// # Panics /// /// It would panic if the range start is not smaller than it's end. -#[instrument(err)] +#[instrument] pub fn check(cookie: &Cookie, fingerprint: u64, valid_range: Range) -> Result { assert!(valid_range.start <= valid_range.end, "range start is larger than range end"); diff --git a/src/servers/udp/handlers.rs b/src/servers/udp/handlers.rs index 1f838cd68..1a9c164e2 100644 --- a/src/servers/udp/handlers.rs +++ b/src/servers/udp/handlers.rs @@ -22,7 +22,7 @@ use super::server::banning::BanService; use super::RawRequest; use crate::core::{statistics, PeersWanted, Tracker}; use crate::servers::udp::error::Error; -use crate::servers::udp::peer_builder; +use crate::servers::udp::{peer_builder, UDP_TRACKER_LOG_TARGET}; use crate::shared::bit_torrent::common::MAX_SCRAPE_TORRENTS; use crate::CurrentClock; @@ -61,7 +61,9 @@ pub(crate) async fn handle_packet( cookie_time_values: CookieTimeValues, ban_service: Arc>, ) -> Response { - tracing::Span::current().record("request_id", Uuid::new_v4().to_string()); + let request_id = Uuid::new_v4(); + + tracing::Span::current().record("request_id", request_id.to_string()); tracing::debug!("Handling Packets: {udp_request:?}"); let start_time = Instant::now(); @@ -84,6 +86,8 @@ pub(crate) async fn handle_packet( handle_error( udp_request.from, + local_addr, + request_id, tracker, cookie_time_values.valid_range.clone(), &e, @@ -92,7 +96,18 @@ pub(crate) async fn handle_packet( .await } }, - Err(e) => handle_error(udp_request.from, tracker, cookie_time_values.valid_range.clone(), &e, None).await, + Err(e) => { + handle_error( + udp_request.from, + local_addr, + request_id, + tracker, + cookie_time_values.valid_range.clone(), + &e, + None, + ) + .await + } }; let latency = start_time.elapsed(); @@ -344,6 +359,8 @@ pub async fn handle_scrape( #[instrument(fields(transaction_id), skip(tracker), ret(level = Level::TRACE))] async fn handle_error( remote_addr: SocketAddr, + local_addr: SocketAddr, + request_id: Uuid, tracker: &Tracker, cookie_valid_range: Range, e: &Error, @@ -351,6 +368,16 @@ async fn handle_error( ) -> Response { tracing::trace!("handle error"); + match transaction_id { + Some(transaction_id) => { + let transaction_id = transaction_id.0.to_string(); + tracing::error!(target: UDP_TRACKER_LOG_TARGET, error = %e, %remote_addr, %local_addr, %request_id, %transaction_id, "response error"); + } + None => { + tracing::error!(target: UDP_TRACKER_LOG_TARGET, error = %e, %remote_addr, %local_addr, %request_id, "response error"); + } + } + let e = if let Error::RequestParseError { request_parse_error } = e { match request_parse_error { RequestParseError::Sendable { From 71e7ef7888768f2a47493b1b7be13a6f989d1f8a Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Thu, 26 Dec 2024 16:34:53 +0000 Subject: [PATCH 3/3] test: [#1164] assert logged error when connection ID is wrong in UDP tracker. Only for the tests that is currently showing logging errors. --- tests/common/fixtures.rs | 7 +++++++ tests/servers/udp/contract.rs | 19 +++++++++++++++---- 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/tests/common/fixtures.rs b/tests/common/fixtures.rs index 562ed1544..f96b03dd1 100644 --- a/tests/common/fixtures.rs +++ b/tests/common/fixtures.rs @@ -1,3 +1,4 @@ +use aquatic_udp_protocol::TransactionId; use bittorrent_primitives::info_hash::InfoHash; #[allow(dead_code)] @@ -20,3 +21,9 @@ pub fn random_info_hash() -> InfoHash { InfoHash::from_bytes(&random_bytes) } + +/// Returns a random transaction id. +pub fn random_transaction_id() -> TransactionId { + let random_value = rand::Rng::gen::(&mut rand::thread_rng()); + TransactionId::new(random_value) +} diff --git a/tests/servers/udp/contract.rs b/tests/servers/udp/contract.rs index ddccf4f9a..9618bef65 100644 --- a/tests/servers/udp/contract.rs +++ b/tests/servers/udp/contract.rs @@ -118,8 +118,8 @@ mod receiving_an_announce_request { use torrust_tracker_configuration::DEFAULT_TIMEOUT; use torrust_tracker_test_helpers::configuration; - use crate::common::fixtures::random_info_hash; - use crate::common::logging; + use crate::common::fixtures::{random_info_hash, random_transaction_id}; + use crate::common::logging::{self, logs_contains_a_line_with}; use crate::servers::udp::asserts::is_ipv4_announce_response; use crate::servers::udp::contract::send_connection_request; use crate::servers::udp::Started; @@ -235,8 +235,6 @@ mod receiving_an_announce_request { Err(err) => panic!("{err}"), }; - let tx_id = TransactionId::new(123); - // The eleven first requests should be fine let invalid_connection_id = ConnectionId::new(0); // Zero is one of the not normal values. @@ -245,11 +243,23 @@ mod receiving_an_announce_request { for x in 0..=10 { tracing::info!("req no: {x}"); + + let tx_id = random_transaction_id(); + send_and_get_announce(tx_id, invalid_connection_id, info_hash, &client).await; + + let transaction_id = tx_id.0.to_string(); + + assert!( + logs_contains_a_line_with(&["ERROR", "UDP TRACKER", &transaction_id.to_string()]), + "Expected logs to contain: ERROR ... UDP TRACKER ... transaction_id={transaction_id}" + ); } // The twelfth request should be banned (timeout error) + let tx_id = random_transaction_id(); + let announce_request = build_sample_announce_request( tx_id, invalid_connection_id, @@ -257,6 +267,7 @@ mod receiving_an_announce_request { info_hash, ); + // This should return a timeout error match client.send(announce_request.into()).await { Ok(_) => (), Err(err) => panic!("{err}"),