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.

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

Write assertions for logged errors #1150

Closed
3 tasks done
josecelano opened this issue Dec 23, 2024 · 5 comments
Closed
3 tasks done

Write assertions for logged errors #1150

josecelano opened this issue Dec 23, 2024 · 5 comments
Assignees
Labels
EPIC Contains several subissues Testing Checking Torrust

Comments

@josecelano
Copy link
Member

josecelano commented Dec 23, 2024

Relates to: #1069
Implement after: #1146

Some tests produce errors in logs. There are expected errors:

cargo test -- --nocapture | grep "ERROR"

We want to add assertions for them.

After merging this PR, we will be able to capture logs in tests.

This issue is better implemented after this one.

Subtasks

Errors in test execution output

These are the three types of errors:

Tracker API:

The tracker API returns a 500 response on some endpoints, in spite of not being a server error.

2024-12-23T16:17:24.085791Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.097523Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.112349Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.134428Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.143296Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.157824Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.165816Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.183568Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.185476Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.187261Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.237987Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.245734Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.672115Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.683863Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.722476Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.726635Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.761522Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.764052Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.795266Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.859246Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.861906Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.885488Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:24.891247Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:25.013874Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:25.340567Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:25.405088Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:25.452089Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T16:17:25.604966Z ERROR API: response failed classification=Status code: 500 Internal Server Error latency=0 ms

Whitelist:

2024-12-23T16:17:25.568154Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23
2024-12-23T16:17:25.630303Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23

UDP connection cookie:

2024-12-23T16:17:26.526503Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5264943
2024-12-23T16:17:26.526537Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5265365
2024-12-23T16:17:26.526556Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.526555
2024-12-23T16:17:26.526572Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5265718
2024-12-23T16:17:26.526588Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5265877
2024-12-23T16:17:26.526605Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266044
2024-12-23T16:17:26.526620Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266197
2024-12-23T16:17:26.526635Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266347
2024-12-23T16:17:26.526652Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266516
2024-12-23T16:17:26.526667Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266664
2024-12-23T16:17:26.526683Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 13655708322282452000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734970647.5266826
@josecelano josecelano added the Testing Checking Torrust label Dec 23, 2024
@josecelano josecelano self-assigned this Dec 23, 2024
@josecelano josecelano added the EPIC Contains several subissues label Dec 23, 2024
josecelano added a commit to josecelano/torrust-tracker that referenced this issue Dec 23, 2024
Some tracing log spans were missing. In adition to that we were using
new spans to log requests and responses instead of using the span
provided by the TraceLayer. That enables to join all the log events
related tho the same requests.

This fix is needed to contunie with this issue:

torrust#1150

Becuase it allos to use a "request-id" header to identify logs.

We can write log assertions by mathich lines with the request-id used in
the request.

For example, it yo make this request:

```console
curl -H "x-request-id: YOUR_REQUEST_ID" http://0.0.0.0:1212/api/v1/stats?token=InvalidToken
```

This is the new output (which was missing before this change):

```output
2024-12-23T17:53:06.530704Z  INFO request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: request method=GET uri=/api/v1/stats?token=InvalidToken request_id=YOUR_REQUEST_ID
2024-12-23T17:53:06.530777Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response latency_ms=0 status_code=500 Internal Server Error request_id=YOUR_REQUEST_ID
2024-12-23T17:53:06.530785Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
```

As you can see. now we have the "request_id=YOUR_REQUEST_ID" field which
can be used to identify the test that made the request.
@josecelano
Copy link
Member Author

josecelano commented Dec 23, 2024

You can run cargo test -- --test-threads=1 --nocapture to identify which tests are logging errors.

And to run only one cargo test -- --test-threads=1 --nocapture should_ban_the_client_ip_if_it_sends_more_than_10_requests_with_a_cookie_value_not_normal.

@josecelano
Copy link
Member Author

josecelano commented Dec 23, 2024

Test producing errors in logs:

$ cargo test -- --test-threads=1 --nocapture

---

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty ... 2024-12-23T18:46:10.685125Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c0c0d658-489c-460c-ac2f-b9a65c99b1eb
2024-12-23T18:46:10.685137Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_invalid ... 2024-12-23T18:46:10.699268Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c24022e9-a659-4879-a4e1-c6cb2c123887
2024-12-23T18:46:10.699278Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_missing ... 2024-12-23T18:46:10.713313Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=a1dcb071-6baf-4c51-954a-25721e508467
2024-12-23T18:46:10.713321Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_fail_when_the_auth_key_cannot_be_generated ... 2024-12-23T18:46:10.769691Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=d6b5222b-d892-4f97-bc4e-46db875e3c99
2024-12-23T18:46:10.769699Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:10.783818Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=1335bfe3-816d-4c68-a0a1-87b805bccd88
2024-12-23T18:46:10.783826Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:10.793807Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=5b21b725-e17c-4145-b2c6-00366447c5bf
2024-12-23T18:46:10.793814Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_fail_when_keys_cannot_be_reloaded ... 2024-12-23T18:46:10.997966Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=6c7b0672-d323-4fa2-9ef8-b6f918a6f422
2024-12-23T18:46:10.997978Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_deleted ... 2024-12-23T18:46:11.016038Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=6e7ea98d-f2da-4e34-9989-14c8af0e54c0
2024-12-23T18:46:11.016046Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_generated ... 2024-12-23T18:46:11.033056Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=aea1d68b-e3b2-45c7-91c9-3987a9934a2c
2024-12-23T18:46:11.033065Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_not_allow_deleting_an_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:11.048427Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=dbda8097-f3ca-4c56-8a94-cd24adcc58a1
2024-12-23T18:46:11.048435Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.059615Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=6815310b-6582-429b-9118-8542c4c8e078
2024-12-23T18:46:11.059624Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:11.074044Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=046b60d2-0e20-4b6d-9d44-a86aa4520911
2024-12-23T18:46:11.074052Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.084212Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=00f5ea8c-1e4d-4ed9-9ea8-2380c56dae93
2024-12-23T18:46:11.084219Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::auth_key::should_not_allow_reloading_keys_for_unauthenticated_users ... 2024-12-23T18:46:11.099531Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=94a8e2ab-b4a8-40a3-8063-c2a136445f6a
2024-12-23T18:46:11.099539Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.109627Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=e2b67f3b-1249-41dd-9081-2fd581bbd8d6
2024-12-23T18:46:11.109634Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::stats::should_not_allow_getting_tracker_statistics_for_unauthenticated_users ... 2024-12-23T18:46:11.152930Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=e0da13a9-7d4e-4d0e-94c3-6203cd346617
2024-12-23T18:46:11.152938Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.163043Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=668a8a7c-1e06-4870-a22a-02a5125ad16a
2024-12-23T18:46:11.163050Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::torrent::should_not_allow_getting_a_torrent_info_for_unauthenticated_users ... 2024-12-23T18:46:11.484403Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=dbe035c1-3345-45b9-9d25-0495cca99c84
2024-12-23T18:46:11.484411Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.494403Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=57943426-8144-47c5-ac77-af95bc5dcf8e
2024-12-23T18:46:11.494410Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::torrent::should_not_allow_getting_torrents_for_unauthenticated_users ... 2024-12-23T18:46:11.508950Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=3cc74693-a589-46b5-93ae-bea37a5072d0
2024-12-23T18:46:11.508960Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.519081Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=d6ce84da-ff6e-4383-a94f-9a9be4e0665e
2024-12-23T18:46:11.519088Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_removed_from_the_whitelist ... 2024-12-23T18:46:11.695539Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=15fee3e8-9717-464c-909d-63620145aaf4
2024-12-23T18:46:11.695547Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_whitelisted ... 2024-12-23T18:46:11.713213Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=d1d8087b-0f16-408f-9e60-a8a4c8106d89

test servers::api::v1::contract::context::whitelist::should_fail_when_the_whitelist_cannot_be_reloaded_from_the_database ... 2024-12-23T18:46:11.731415Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c23f7e5a-d5ab-4ccf-bbda-2e0d4685b33a
2024-12-23T18:46:11.731423Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::whitelist::should_not_allow_removing_a_torrent_from_the_whitelist_for_unauthenticated_users ... 2024-12-23T18:46:11.831375Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=aee93b39-3e05-49d9-8529-98e635e39a73
2024-12-23T18:46:11.831383Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.841538Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=a030eabd-b07d-4466-b629-e997e7da30c4
2024-12-23T18:46:11.841545Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::api::v1::contract::context::whitelist::should_not_allow_whitelisting_a_torrent_for_unauthenticated_users ... 2024-12-23T18:46:11.855691Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=7891d303-f970-465b-b9b0-b4fc7a559dfa
2024-12-23T18:46:11.855699Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
2024-12-23T18:46:11.865843Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=39d5afe5-a3ad-4205-b585-fbffbc38568a
2024-12-23T18:46:11.865850Z ERROR API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms

test servers::health_check_api::contract::api::it_should_return_error_when_api_service_was_stopped_after_registration ... !! 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 ... 2024-12-23T18:46:14.180931Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23

test servers::http::v1::contract::configured_as_whitelisted::receiving_an_scrape_request::should_return_the_zeroed_file_when_the_requested_file_is_not_whitelisted ... 2024-12-23T18:46:14.209989Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23

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: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1698081
2024-12-23T18:46:15.169870Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1698694
2024-12-23T18:46:15.169886Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1698856
2024-12-23T18:46:15.169901Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699007
2024-12-23T18:46:15.169915Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.169915
2024-12-23T18:46:15.169929Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699286
2024-12-23T18:46:15.169943Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699426
2024-12-23T18:46:15.169957Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699564
2024-12-23T18:46:15.169970Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.16997
2024-12-23T18:46:15.169984Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699839
2024-12-23T18:46:15.169998Z ERROR torrust_tracker::servers::udp::connection_cookie: error=cookie value is from future: 31954395241256854000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000, expected < 1734979576.1699982

@josecelano
Copy link
Member Author

josecelano commented Dec 23, 2024

Updated list of tests producing errors in logs (22 in total):

API (19):

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty ... 2024-12-23T18:46:10.685125Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c0c0d658-489c-460c-ac2f-b9a65c99b1eb
test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_invalid ... 2024-12-23T18:46:10.699268Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c24022e9-a659-4879-a4e1-c6cb2c123887
test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_missing ... 2024-12-23T18:46:10.713313Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=a1dcb071-6baf-4c51-954a-25721e508467
test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_fail_when_the_auth_key_cannot_be_generated ... 2024-12-23T18:46:10.769691Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=d6b5222b-d892-4f97-bc4e-46db875e3c99
test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:10.783818Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=1335bfe3-816d-4c68-a0a1-87b805bccd88
test servers::api::v1::contract::context::auth_key::should_fail_when_keys_cannot_be_reloaded ... 2024-12-23T18:46:10.997966Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=6c7b0672-d323-4fa2-9ef8-b6f918a6f422
test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_deleted ... 2024-12-23T18:46:11.016038Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=6e7ea98d-f2da-4e34-9989-14c8af0e54c0
test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_generated ... 2024-12-23T18:46:11.033056Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=aea1d68b-e3b2-45c7-91c9-3987a9934a2c
test servers::api::v1::contract::context::auth_key::should_not_allow_deleting_an_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:11.048427Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=dbda8097-f3ca-4c56-8a94-cd24adcc58a1
test servers::api::v1::contract::context::auth_key::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... 2024-12-23T18:46:11.074044Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=046b60d2-0e20-4b6d-9d44-a86aa4520911
test servers::api::v1::contract::context::auth_key::should_not_allow_reloading_keys_for_unauthenticated_users ... 2024-12-23T18:46:11.099531Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=94a8e2ab-b4a8-40a3-8063-c2a136445f6a
test servers::api::v1::contract::context::stats::should_not_allow_getting_tracker_statistics_for_unauthenticated_users ... 2024-12-23T18:46:11.152930Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=e0da13a9-7d4e-4d0e-94c3-6203cd346617
test servers::api::v1::contract::context::torrent::should_not_allow_getting_a_torrent_info_for_unauthenticated_users ... 2024-12-23T18:46:11.484403Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=dbe035c1-3345-45b9-9d25-0495cca99c84
test servers::api::v1::contract::context::torrent::should_not_allow_getting_torrents_for_unauthenticated_users ... 2024-12-23T18:46:11.508950Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=3cc74693-a589-46b5-93ae-bea37a5072d0
test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_removed_from_the_whitelist ... 2024-12-23T18:46:11.695539Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=15fee3e8-9717-464c-909d-63620145aaf4
test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_whitelisted ... 2024-12-23T18:46:11.713213Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=d1d8087b-0f16-408f-9e60-a8a4c8106d89
test servers::api::v1::contract::context::whitelist::should_fail_when_the_whitelist_cannot_be_reloaded_from_the_database ... 2024-12-23T18:46:11.731415Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=c23f7e5a-d5ab-4ccf-bbda-2e0d4685b33a
test servers::api::v1::contract::context::whitelist::should_not_allow_removing_a_torrent_from_the_whitelist_for_unauthenticated_users ... 2024-12-23T18:46:11.831375Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=aee93b39-3e05-49d9-8529-98e635e39a73
test servers::api::v1::contract::context::whitelist::should_not_allow_whitelisting_a_torrent_for_unauthenticated_users ... 2024-12-23T18:46:11.855691Z ERROR API: response latency_ms=0 status_code=500 Internal Server Error request_id=7891d303-f970-465b-b9b0-b4fc7a559dfa

HTTP Tracker:

test servers::http::v1::contract::configured_as_whitelisted::and_receiving_an_announce_request::should_fail_if_the_torrent_is_not_in_the_whitelist ... 2024-12-23T18:46:14.180931Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23
test servers::http::v1::contract::configured_as_whitelisted::receiving_an_scrape_request::should_return_the_zeroed_file_when_the_requested_file_is_not_whitelisted ... 2024-12-23T18:46:14.209989Z ERROR torrust_tracker::core: error=The torrent: 9c38422213e30bff212b30c360d26f9a02136422, is not whitelisted, src/core/mod.rs:1108:23

UDP Tracker:

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:

cc @da2ce7

josecelano added a commit that referenced this issue Dec 23, 2024
97233f5 fix: missing logs for HTTP requests (Jose Celano)

Pull request description:

  Relates to:
    - #1150
    - #1152

  Some log lines (tracing spans) were missing. In addition to that, we were using new spans to log requests and responses instead of using the span provided by the `TraceLayer`. That enables you to join all the log events related to the same request.

  This fix is needed to continue with this issue: #1150

  Because it allows the use of a "request-id" header to identify logs.

  We can write log assertions by matching lines with the `request-id` used in the request.

  For example, if you make this request:

  ```console
  curl -H "x-request-id: YOUR_REQUEST_ID" http://0.0.0.0:1212/api/v1/stats?token=InvalidToken
  ```

  This is the new output (which was missing before this change):

  ```output
  2024-12-23T17:53:06.530704Z  INFO request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: request method=GET uri=/api/v1/stats?token=InvalidToken request_id=YOUR_REQUEST_ID
  2024-12-23T17:53:06.530777Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response latency_ms=0 status_code=500 Internal Server Error request_id=YOUR_REQUEST_ID
  2024-12-23T17:53:06.530785Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms
  ```

  As you can see, now we have the "request_id=YOUR_REQUEST_ID" field, which can be used to identify the test that made the request and write a log assertion for that concrete expected line.

ACKs for top commit:
  josecelano:
    ACK 97233f5

Tree-SHA512: 075a3cdeafa735d4a263c942b34594049adc9d42ed5e8a1bef043ffea394bfdae7cf109928f1311d4589f40804c72ebe71c66d6ec5380f5ce472ba9ba5304ad5
@josecelano
Copy link
Member Author

You can run a single test with:

cargo test -- --nocapture servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty

@josecelano
Copy link
Member Author

All subtasks implemented.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
EPIC Contains several subissues Testing Checking Torrust
Projects
None yet
Development

No branches or pull requests

1 participant