Sdterror output from tracing running tests

[josecelano]

When you run the tests you see some errors in the stderror

test servers::api::v1::contract::context::torrent::should_allow_limiting_the_torrents_in_the_result ... ok
  2024-11-01T09:27:25.702371Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_fail_when_keys_cannot_be_reloaded ... ok
  2024-11-01T09:27:25.711737Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

  2024-11-01T09:27:25.713069Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty ... ok
  2024-11-01T09:27:25.723461Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_missing ... ok
  2024-11-01T09:27:25.725770Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

  2024-11-01T09:27:25.746900Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

  2024-11-01T09:27:25.749262Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_generated ... ok
test servers::api::v1::contract::context::auth_key::should_allow_uploading_a_preexisting_auth_key ... ok
test servers::api::v1::contract::context::auth_key::should_allow_deleting_an_auth_key ... ok
  2024-11-01T09:27:25.774618Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

  2024-11-01T09:27:25.775134Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_deleted ... ok
test servers::api::v1::contract::context::torrent::should_allow_getting_a_list_of_torrents_providing_infohashes ... ok
  2024-11-01T09:27:25.797612Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::torrent::should_allow_getting_all_torrents ... ok
test servers::api::v1::contract::context::stats::should_allow_getting_tracker_statistics ... ok
test servers::api::v1::contract::authentication::should_allow_the_token_query_param_to_be_at_any_position_in_the_url_query ... ok
test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_fail_generating_a_new_auth_key_when_the_key_duration_is_invalid ... ok
  2024-11-01T09:27:26.242719Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::torrent::should_fail_while_getting_a_torrent_info_when_the_torrent_does_not_exist ... ok
  2024-11-01T09:27:26.297102Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::whitelist::should_allow_reload_the_whitelist_from_the_database ... ok
test servers::api::v1::contract::context::whitelist::should_allow_whitelisting_a_torrent ... ok
test servers::api::v1::contract::context::whitelist::should_allow_removing_a_torrent_from_the_whitelist ... ok
  2024-11-01T09:27:26.361616Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::whitelist::should_fail_when_the_whitelist_cannot_be_reloaded_from_the_database ... ok
  2024-11-01T09:27:26.383337Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

  2024-11-01T09:27:26.383617Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_not_allow_deleting_an_auth_key_for_unauthenticated_users ... ok
  2024-11-01T09:27:26.388780Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... ok
  2024-11-01T09:27:26.391286Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_whitelisted ... ok
  2024-11-01T09:27:26.401139Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::stats::should_not_allow_getting_tracker_statistics_for_unauthenticated_users ... ok
  2024-11-01T09:27:26.407532Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_removed_from_the_whitelist ... ok
test servers::api::v1::contract::context::whitelist::should_not_fail_trying_to_remove_a_non_whitelisted_torrent_from_the_whitelist ... ok
  2024-11-01T09:27:26.442571Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users ... ok
  2024-11-01T09:27:26.453664Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_fail_generating_a_new_auth_key_when_the_key_duration_is_invalid ... ok
  2024-11-01T09:27:26.472636Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::auth_key::should_not_allow_reloading_keys_for_unauthenticated_users ... ok
test servers::health_check_api::contract::health_check_endpoint_should_return_status_ok_when_there_is_no_services_registered ... ok
test servers::http::v1::contract::environment_should_be_started_and_stopped ... ok
  2024-11-01T09:27:26.893709Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::torrent::should_not_allow_getting_a_torrent_info_for_unauthenticated_users ... ok
test servers::health_check_api::contract::udp::it_should_return_good_health_for_udp_service ... ok
test servers::http::v1::contract::configured_as_private::receiving_an_scrape_request::should_fail_if_the_key_query_param_cannot_be_parsed ... ok
  2024-11-01T09:27:26.993979Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::torrent::should_not_allow_getting_torrents_for_unauthenticated_users ... ok
test servers::http::v1::contract::for_all_config_modes::receiving_an_announce_request::it_should_start_and_stop ... ok
test servers::http::v1::contract::configured_as_private::and_receiving_an_announce_request::should_fail_if_the_peer_has_not_provided_the_authentication_key ... ok
test servers::http::v1::contract::configured_as_private::and_receiving_an_announce_request::should_fail_if_the_key_query_param_cannot_be_parsed ... ok
test servers::api::v1::contract::context::whitelist::should_allow_whitelisting_a_torrent_that_has_been_already_whitelisted ... ok
  2024-11-01T09:27:27.047456Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

test servers::api::v1::contract::context::whitelist::should_not_allow_whitelisting_a_torrent_for_unauthenticated_users ... ok
test servers::http::v1::contract::configured_as_whitelisted::and_receiving_an_announce_request::should_allow_announcing_a_whitelisted_torrent ... ok
test servers::http::v1::contract::configured_as_private::and_receiving_an_announce_request::should_respond_to_authenticated_peers ... ok
test servers::http::v1::contract::configured_as_private::and_receiving_an_announce_request::should_fail_if_the_peer_cannot_be_authenticated_with_the_provided_key ... ok
test servers::http::v1::contract::configured_as_private::receiving_an_scrape_request::should_return_the_zeroed_file_when_the_client_is_not_authenticated ... ok
test servers::http::v1::contract::configured_as_private::receiving_an_scrape_request::should_return_the_real_file_stats_when_the_client_is_authenticated ... ok
  2024-11-01T09:27:27.110995Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 0 ms
    at /home/josecelano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.6.1/src/trace/on_failure.rs:93

You can run the tests with command 2>/dev/null, but we should disable that output in tracing when running the tests.

[da2ce7]

Hmmm... I think that having the ERROR go through to the STDERR in tests is a good thing... For these cases we should idivitually look into each on, and see if the error is really an error, or it is limitation of our reporting, or we should lower the warning to WARN... or it is a real error, and we disable the tracing for that individual test, (with a comment why).

[mario-nt]

@da2ce7 I would add a new config option to set the tracing level for the tests in the toml file. And still have the tracing_stderr_init function to override that tracing level on tests when needed, as I think having that function called in every test adds a bit of repeated code.

Regarding having tracing on tests, I think it can be useful for development, but I think it is better if we just show an OK or FAIL result when running them, I will do some research on the topic anyway.

[josecelano]

Hi @da2ce7 and @mario-nt, the reason those tests are returning a 500 error is to keep compatibility with the old API.

Before migrating to Axum, the previous API returned a 500 for all these cases. I decided not to break the contract in the migration and wait until the new API.

These are the cases in tests:

pub async fn assert_token_not_valid(response: Response) {
    assert_unhandled_rejection(response, "token not valid").await;
}

pub async fn assert_unauthorized(response: Response) {
    assert_unhandled_rejection(response, "unauthorized").await;
}

pub async fn assert_failed_to_remove_torrent_from_whitelist(response: Response) {
    assert_unhandled_rejection(response, "failed to remove torrent from whitelist").await;
}

pub async fn assert_failed_to_whitelist_torrent(response: Response) {
    assert_unhandled_rejection(response, "failed to whitelist torrent").await;
}

pub async fn assert_failed_to_reload_whitelist(response: Response) {
    assert_unhandled_rejection(response, "failed to reload whitelist").await;
}

pub async fn assert_failed_to_generate_key(response: Response) {
    assert_unhandled_rejection(response, "failed to generate key").await;
}

pub async fn assert_failed_to_delete_key(response: Response) {
    assert_unhandled_rejection(response, "failed to delete key").await;
}

pub async fn assert_failed_to_reload_keys(response: Response) {
    assert_unhandled_rejection(response, "failed to reload keys").await;
}

async fn assert_unhandled_rejection(response: Response, reason: &str) {
    assert_eq!(response.status(), 500);
    assert_eq!(response.headers().get("content-type").unwrap(), "text/plain; charset=utf-8");

    let reason_text = format!("Unhandled rejection: Err {{ reason: \"{reason}");
    let response_text = response.text().await.unwrap();
    assert!(
        response_text.contains(&reason_text),
        ":\n  response: `\"{response_text}\"`\n  does not contain: `\"{reason_text}\"`."
    );
}

The tests are all from the API:

servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_empty
servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_invalid
servers::api::v1::contract::authentication::should_not_authenticate_requests_when_the_token_is_missing
servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_fail_when_the_auth_key_cannot_be_generated
servers::api::v1::contract::context::auth_key::deprecated_generate_key_endpoint::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users
servers::api::v1::contract::context::auth_key::should_fail_when_keys_cannot_be_reloaded
servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_deleted
servers::api::v1::contract::context::auth_key::should_fail_when_the_auth_key_cannot_be_generated
servers::api::v1::contract::context::auth_key::should_not_allow_deleting_an_auth_key_for_unauthenticated_users
servers::api::v1::contract::context::auth_key::should_not_allow_generating_a_new_auth_key_for_unauthenticated_users
servers::api::v1::contract::context::auth_key::should_not_allow_reloading_keys_for_unauthenticated_users
servers::api::v1::contract::context::stats::should_not_allow_getting_tracker_statistics_for_unauthenticated_users
servers::api::v1::contract::context::torrent::should_not_allow_getting_a_torrent_info_for_unauthenticated_users
servers::api::v1::contract::context::torrent::should_not_allow_getting_torrents_for_unauthenticated_users
servers::api::v1::contract::context::whitelist::should_fail_when_the_torrent_cannot_be_removed_from_the_whitelist
servers::api::v1::contract::context::whitelist::should_fail_when_the_whitelist_cannot_be_reloaded_from_the_database
servers::api::v1::contract::context::whitelist::should_not_allow_removing_a_torrent_from_the_whitelist_for_unauthenticated_users
servers::api::v1::contract::context::whitelist::should_not_allow_whitelisting_a_torrent_for_unauthenticated_users
servers::http::v1::contract::configured_as_whitelisted::and_receiving_an_announce_request::should_fail_if_the_torrent_is_not_in_the_whitelist
servers::http::v1::contract::configured_as_whitelisted::receiving_an_scrape_request::should_return_the_zeroed_file_when_the_requested_file_is_not_whitelisted

I think we should do what we agreed on in the meeting. We should:

• Capture the expected error in the logs
• Assert that the ERROR was sent to the logs

For example, in this test:

#[tokio::test]
async fn should_not_authenticate_requests_when_the_token_is_empty() {
    INIT.call_once(|| {
        tracing_stderr_init(LevelFilter::ERROR);
    });

    let env = Started::new(&configuration::ephemeral().into()).await;

    let response = Client::new(env.get_connection_info())
        .get_request_with_query("stats", Query::params([QueryParam::new("token", "")].to_vec()))
        .await;

    assert_token_not_valid(response).await;

    env.stop().await;
}

We can change the test to something like:

use tracing::Level;
use tracing_subscriber::fmt::TestWriter;
use tracing_subscriber::prelude::*;

#[tokio::test]
async fn should_not_authenticate_requests_when_the_token_is_empty() {
    let log_writer = TestWriter::new();
    let subscriber = tracing_subscriber::fmt()
        .with_writer(log_writer.clone())
        .with_max_level(Level::ERROR)
        .finish();

    let _guard = tracing::subscriber::set_default(subscriber);

    let env = Started::new(&configuration::ephemeral().into()).await;

    let response = Client::new(env.get_connection_info())
        .get_request_with_query("stats", Query::params([QueryParam::new("token", "")].to_vec()))
        .await;

    assert_token_not_valid(response).await;

    env.stop().await;

    // Ensure the log contains the expected error
    let logs = log_writer.to_string();
    assert!(
        logs.contains("response failed, classification: Status code: 500 Internal Server Error"),
        "Expected error log was not found in the captured logs: {}",
        logs
    );
}

We can start with the most straightforward implementation and see later whether we can extract this into a test helper or move the logic to the configuration::ephemeral() factory. A helper seems like a good option because, in fact, login setup is done for the whole app, not for a specific service (API).

I would fix all tests with this pattern to remove the errors. There are only a few of them.

[josecelano]

Hi @mario-nt I'm working on a PR that will add more errors like these. I won't "hide" them in that PR to avoid conflicts with this issue. It's easier to fix all of them at the same time.

[josecelano]

Hi @mario-nt I'm working on a PR that will add more errors like these. I won't "hide" them in that PR to avoid conflicts with this issue. It's easier to fix all of them at the same time.

The error is this:

  2024-12-09T16:13:10.908628Z ERROR torrust_tracker::servers::udp::connection_cookie: error: cookie value is expired: 0.00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000006166606896726832, expected > 1733760669.9086268
    at src/servers/udp/connection_cookie.rs:124

[josecelano]

Hi @mario-nt, I'm also working on this. The TestWriter is just to ignore output. I think we have to implement a Writer to capture the logs in tests.

[josecelano]

The errors come from the tower_http's struct TracerLayer that uses the DefaultOnFailure struct.

We can customize the error calling .on_failure:

#[allow(clippy::needless_pass_by_value)]
#[instrument(skip(tracker, access_tokens))]
pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> Router {
    let router = Router::new();

    let api_url_prefix = "/api";

    let router = v1::routes::add(api_url_prefix, router, tracker.clone());

    let state = State { access_tokens };

    router
        .layer(middleware::from_fn_with_state(state, v1::middlewares::auth::auth))
        .route(&format!("{api_url_prefix}/health_check"), get(health_check_handler))
        .layer(CompressionLayer::new())
        .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid))
        .layer(PropagateHeaderLayer::new(HeaderName::from_static("x-request-id")))
        .layer(
            TraceLayer::new_for_http()
                .make_span_with(DefaultMakeSpan::new().level(Level::INFO))
                .on_request(|request: &Request<axum::body::Body>, _span: &Span| {
                    let method = request.method().to_string();
                    let uri = request.uri().to_string();
                    let request_id = request
                        .headers()
                        .get("x-request-id")
                        .map(|v| v.to_str().unwrap_or_default())
                        .unwrap_or_default();

                    tracing::span!(
                        target: API_LOG_TARGET,
                        tracing::Level::INFO, "request", method = %method, uri = %uri, request_id = %request_id);
                })
                .on_response(|response: &Response, latency: Duration, _span: &Span| {
                    let status_code = response.status();
                    let request_id = response
                        .headers()
                        .get("x-request-id")
                        .map(|v| v.to_str().unwrap_or_default())
                        .unwrap_or_default();
                    let latency_ms = latency.as_millis();

                    tracing::span!(
                        target: API_LOG_TARGET,
                        tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id);
                })
                .on_failure(
                    |failure_classification: ServerErrorsFailureClass, _latency: Duration, _span: &Span| {
                        tracing::error!(target: API_LOG_TARGET, "response failed, classification: {failure_classification}");
                    },
                ),
        )
        .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid))
        .layer(
            ServiceBuilder::new()
                // this middleware goes above `TimeoutLayer` because it will receive
                // errors returned by `TimeoutLayer`
                .layer(HandleErrorLayer::new(|_: BoxError| async { StatusCode::REQUEST_TIMEOUT }))
                .layer(TimeoutLayer::new(DEFAULT_TIMEOUT)),
        )
}

I would override it even if we print the same message to avoid depending on the third-party error when writing assertions in tests. It's also easier to find the code when you see the error in logs.

The extra code:

.on_failure(
                    |failure_classification: ServerErrorsFailureClass, _latency: Duration, _span: &Span| {
                        tracing::error!(target: API_LOG_TARGET, "response failed, classification: {failure_classification}");
                    },
                ),