Integration tests for UDP Tracker

[josecelano]

I'm trying to reproduce the error in issue #42. I've only created the scaffolding for integration tests so far.

If there is no bug I want to use this scaffolding for other integration tests. If we consider them helpful.

[josecelano]

hi @da2ce7 @WarmBeer I have added three tests:

• should_return_a_bad_request_response_when_the_client_sends_an_empty_request
• should_return_a_connect_response_when_the_client_sends_a_connection_request
• should_return_an_announce_response_when_the_client_sends_an_announce_request

After adding the third one, I started having random failures for the third one. First, I send the "connect" request and then the "announce" request. For some reason, the client does not receive the "announce" response, but the server is sending it (I see it in the log).

If I comment out the first two tests, It always works, so tests must not be isolated.
I'm using a different client instance with a different local port for each test to be sure clients do not collide.

[josecelano]

Sometimes I get this message:

2022-10-06T19:36:29.518810036+01:00 [torrust_tracker::logging][INFO] logging initialized.
2022-10-06T19:36:29.518884993+01:00 [torrust_tracker::jobs::udp_tracker][INFO] Starting UDP server on: 127.0.0.1:6969
test udp_tracker_server::should_return_a_bad_request_response_when_the_client_sends_an_empty_request ... ok
thread 'udp_tracker_server::should_return_an_announce_response_when_the_client_sends_an_announce_request' panicked at 'called `Result::unwrap()` on an `Err` value: Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }', tests/udp.rs:118:43
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test udp_tracker_server::should_return_a_connect_response_when_the_client_sends_a_connection_request ... ok
test udp_tracker_server::should_return_an_announce_response_when_the_client_sends_an_announce_request ... FAILED

failures:

failures:
    udp_tracker_server::should_return_an_announce_response_when_the_client_sends_an_announce_request

test result: FAILED. 2 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

And sometimes, the tests stop at the third test (there is no timeout for the "receive" data function).

If I stop the test execution with "CTRL+C" the socket is not close because there is still a thread (I suppose it is the udp server).

[mickvandijke]

Hey @josecelano ,

When you run the tests synchronously Eg:

#[tokio::test]
async fn test() {
    should_return_a_bad_request_response_when_the_client_sends_an_empty_request().await;
    should_return_a_connect_response_when_the_client_sends_a_connection_request().await;
    should_return_an_announce_response_when_the_client_sends_an_announce_request().await;
}

They pass 100% of the time.

I think when you run the tests at the same time, each of the tests will try and boot up a new udp tracker while all the tests are ongoing. This probably leads to packet loss.

So to fix it, we either have to run the tests synchronously or provide each test with its own UdpServer (on a unique port).

[josecelano]

hi @WarmBeer @da2ce7, I've also added the test for the scrape request. I think it's ready for review. I only check basic behaviour. Only the happy path, and I only check the response type. Particular cases are (or should) be covered by unit tests. If you think that other tests could be helpful, let me know.

Maybe adding more tests to cover the full specification would be nice. That would be useful to run smoke tests against live UDP servers. But maybe it makes more sense to use a real client for that and make it an independent project.

[da2ce7]

@WarmBeer Why do you introduce this change here? It seems unrelated.

[josecelano]

hi @da2ce7 We're using an independent UdpServer for each test, so we isolate tests.

    impl UdpServer {
       // ..

        pub async fn start(&mut self, configuration: Arc<Configuration>) {
            if !self.started.load(Ordering::Relaxed) {
                // ...

                // Initialize logging
                logging::setup_logging(&configuration);

                // ...
            }
        }
    }

The problem is each UdpServer instance tries to setup logging again with:

    if let Err(_err) = fern::Dispatch::new()
        .format(|out, message, record| {
            out.finish(format_args!(
                "{} [{}][{}] {}",
                chrono::Local::now().format("%+"),
                record.target(),
                record.level(),
                message
            ))
        })
        .level(log_level)
        .chain(std::io::stdout())
        .apply()
    {
        panic!("Failed to initialize logging.")
    }

I do not know how that code works, but I suppose is a kind of "pipe" to redirect the log to the stdout, and probably that can be done only once. If that is the case, we have these options:

1. What @WarmBeer did. We can disable log for testing. I do not like this solution because, very often, logging is helpful during testing. I use it a lot.
2. We can setup logging in a different way for testing, for example, using a different log file for each server. I do not like this option. It generates too much garbage.
3. We can use a different setup_logging for tests where we ensure we only call once the "pipe" generation code.
4. We can change setup_logging function in the production code to avoid calling that part twice, regardless the log level you want.

I would go for option 4.

[josecelano]

hi @da2ce7 @WarmBeer, I've changed the setup_logging function to avoid panicking if it's called more than once. This way, we can enable logging even for testing (using more than one UdpServe). I still use the "off" level in testing because I prefer to keep the test output clean. You can enable it whenever you needed it.

[da2ce7]

What happens, is it not possible for the logs to be tracker-local?

[josecelano]

Yes, I think it's possible. Read my comment avobe.

[da2ce7]

ACK 5dcea43