Log assertions: add assertions for log errors in UDP tracker

[josecelano]

Parent issue: #1150
Relates to:

test servers::udp::contract::receiving_an_announce_request::should_ban_the_client_ip_if_it_sends_more_than_10_requests_with_a_cookie_value_not_normal ... 2024-12-23T18:46:15.169819Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future:

You can run a single test with:

cargo test -- --nocapture servers::http::v1::contract::configured_as_whitelisted::and_receiving_an_announce_request::should_fail_if_the_torrent_is_not_in_the_whitelist

The output:

2024-12-26T11:48:17.599803Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23
!! shuting down in 90 seconds !!
test servers::http::v1::contract::configured_as_whitelisted::and_receiving_an_announce_request::should_fail_if_the_torrent_is_not_in_the_whitelist ... ok

[josecelano]

Hi @da2ce7, for the UDP tracker, the ERRORs in the logs come from using #[instrument(err)] in the check function.

#[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");

    // ...

    Ok(issue_time)
}

I think we should not write test assertions for things we don't control directly. If we want to include an assert in tests for this log error:

2024-12-26T12:23:45.259672Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.259648

we should write our error before returning the error response. I will do that and I will include the info-hash and request-id in the error.

The test:

$ cargo test -- --nocapture should_ban_the_client_ip_if_it_sends_more_than_10_requests_with_a_cookie_value_not_normal

The test output with log errors:

running 1 test
2024-12-26T12:23:45.259672Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.259648
2024-12-26T12:23:45.259723Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597222
2024-12-26T12:23:45.259739Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597384
2024-12-26T12:23:45.259755Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597547
2024-12-26T12:23:45.259768Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597682
2024-12-26T12:23:45.259782Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597814
2024-12-26T12:23:45.259797Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2597966
2024-12-26T12:23:45.259810Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2598097
2024-12-26T12:23:45.259826Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2598255
2024-12-26T12:23:45.259838Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2598383
2024-12-26T12:23:45.259852Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 10377356095909847000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1735215826.2598515
test servers::udp::contract::receiving_an_announce_request::should_ban_the_client_ip_if_it_sends_more_than_10_requests_with_a_cookie_value_not_normal ... ok