Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Log assertions: add assertions for log errors in UDP tracker #1164

Closed
Tracked by #1150
josecelano opened this issue Dec 26, 2024 · 1 comment · Fixed by #1165
Closed
Tracked by #1150

Log assertions: add assertions for log errors in UDP tracker #1164

josecelano opened this issue Dec 26, 2024 · 1 comment · Fixed by #1165
Assignees
@josecelano
Labels
Testing Checking Torrust

Comments

@josecelano
Copy link
Member

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 josecelano self-assigned this Dec 26, 2024
@josecelano josecelano added the Testing Checking Torrust label Dec 26, 2024
@josecelano
Copy link
Member Author

josecelano commented Dec 26, 2024 •
edited
Loading

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

@josecelano josecelano mentioned this issue Dec 26, 2024
Closed
3 tasks
josecelano added a commit to josecelano/torrust-tracker that referenced this issue Dec 26, 2024
@josecelano
test: [torrust#1164] assert logged error when connection ID is wrong
71e7ef7 
in UDP tracker. Only for the tests that is currently showing logging
errors.
@josecelano josecelano linked a pull request Dec 26, 2024 that will close this issue
Log assertions: add assertions for log errors in UDP tracker #1165
Merged
@josecelano josecelano mentioned this issue Dec 26, 2024
Open
josecelano added a commit that referenced this issue Dec 26, 2024
@josecelano
Merge #1165: Log assertions: add assertions for log errors in UDP tra…
4291bba 
…cker

71e7ef7 test: [#1164] assert logged error when connection ID is wrong (Jose Celano)
5f206f0 feat: add more fields to UDP error response log (Jose Celano)
33e72bb tests: add info-hash to announce req fixture (Jose Celano)

Pull request description:

  When you run this test:

  ```console
  cargo test -- --nocapture should_ban_the_client_ip_if_it_sends_more_than_10_requests_with_a_cookie_value_not_normal
  ```

  It produces errors in logs:

  ```
  2024-12-26T16:36:47.110017Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1099956 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=37145179-19a4-4dee-8de4-38bf78adb947 transaction_id=-1197696568
  2024-12-26T16:36:47.110065Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.110063 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=67ef896d-6cae-40d5-9579-861b3f0bcc08 transaction_id=-1981380796
  2024-12-26T16:36:47.110083Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.110082 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=2c8468b5-dd98-42c6-a7f1-729e24fcd4d1 transaction_id=1019576994
  2024-12-26T16:36:47.110101Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1100998 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=5136e93c-d37a-4170-b7d4-60c89085d716 transaction_id=-1112877121
  2024-12-26T16:36:47.110120Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1101193 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=7d64e196-d5e1-4e9a-8d73-04edd6abd058 transaction_id=-178038086
  2024-12-26T16:36:47.110140Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1101387 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=ca4649c8-182f-4478-9320-45bc5fbf05cf transaction_id=-1291900102
  2024-12-26T16:36:47.110158Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1101577 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=a421124b-7dd8-40d0-aaee-adbc490633d0 transaction_id=-572700157
  2024-12-26T16:36:47.110179Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1101787 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=5ee806b6-8774-407e-8fca-7ab2c8f9f614 transaction_id=-819492118
  2024-12-26T16:36:47.110199Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1101985 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=f28523bc-4413-431d-85c6-63b4007a386d transaction_id=-958244248
  2024-12-26T16:36:47.110220Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.110219 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=271ded0a-acc7-431d-abd9-ca56cb9139fc transaction_id=1716116781
  2024-12-26T16:36:47.110241Z ERROR UDP TRACKER: response error error=cookie value is expired: -0.00000000000000000004989914643359549, expected > 1735230886.1102402 remote_addr=127.0.0.1:34493 local_addr=127.0.0.1:34443 request_id=af8211e6-3c42-49dc-b891-e936bdbb38ab transaction_id=539714610
  ```

  This PR adds assertions for those logs.

ACKs for top commit:
  josecelano:
    ACK 71e7ef7

Tree-SHA512: 4274978ff2736a9ea94ef35e1988c218b558e8b09f18005e0e4bcedad34dea75601bdde958608f0e8364121563f702ff78ef3e0e9be496542e9a5f04084ad491
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@josecelano josecelano

Labels
Testing Checking Torrust
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Log assertions: add assertions for log errors in UDP tracker josecelano/torrust-tracker
1 participant
@josecelano