Strange delays for rumqttd on Windows

[wardru]

Hello,

I'm having some issues using rumqttd on Windows, here the following details.
Thanks for the help!

Expected Behavior

I expect a client to connect immediately to a rumqttd broker on Windows.

Current Behavior

On Linux, the client connects immediately to a running rumqttd broker.
On Windows, there seem to be a delay of ~2 seconds before a successful connection.
This issue only happens is the broker is running before the client does.
If the client is running before (and gets rejected because the broker is not running), then the connection will be immediate when I run the broker.

Also out of curiosity, even though this is not really part of the problem, I wonder why the retry attempt when polling the event loop on Windows includes a delay of ~5 seconds when a connection fails.
On Linux, polling the event loop as fast as possible will spam rejection attempts.

Context

Windows:

Edition	Windows 11 Home
Version	24H2
Installed on	‎11/‎28/‎2024
OS build	26100.2314
Experience	Windows Feature Experience Pack 1000.26100.32.0

Rust:

rustc 1.83.0 (90b35a623 2024-11-26)

Rumqttd:
Running the basic example for the broker with:

cargo run --release --bin rumqttd -- -c ./rumqttd/rumqttd.toml -vvv

My very basic client:

use rumqttc::{AsyncClient, MqttOptions};
use std::time::Duration;
use tokio;

#[tokio::main]
async fn main() {
    let mut opts = MqttOptions::new("test", "localhost", 1883);
    opts.set_keep_alive(Duration::from_secs(1));

    let (_, mut event_loop) = AsyncClient::new(opts, 10);

    loop {
        let event = &event_loop.poll().await;
        println!("event: {event:?}");
    }
}

Failure Logs

This is a log from the broker with a client ran simultaneously:

warning: `rumqttd` (lib) generated 1 warning
    Finished `release` profile [optimized] target(s) in 0.33s
     Running `target\release\rumqttd.exe -c ./rumqttd/rumqttd.toml -vvv`

         ___ _   _ __  __  ___ _____ _____ ___
        | _ \ | | |  \/  |/ _ \_   _|_   _|   \
        |   / |_| | |\/| | (_) || |   | | | |) |
        |_|_\\___/|_|  |_|\__\_\|_|   |_| |___/


  2024-11-30T13:51:32.620455Z TRACE rumqttd::router::routing: Validating Client ID = console
    in rumqttd::router::routing::[>] incoming with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.620798Z  INFO rumqttd::router::routing: Client connection registered, connection_id: 0
    in rumqttd::router::routing::incoming_connect with client_id: "console"
    in rumqttd::router::routing::[>] incoming with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.621012Z TRACE rumqttd::router::scheduler: reschedule Busy -> Ready, tracker_id: "console"
    in rumqttd::router::routing::incoming_connect with client_id: "console"
    in rumqttd::router::routing::[>] incoming with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.621222Z TRACE rumqttd::router::routing: Consuming requests
    in rumqttd::router::routing::[<] outgoing with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.621417Z TRACE rumqttd::router::routing: Ack added for pkid 0, pkid: 0
    in rumqttd::router::routing::outgoing_ack with client_id: "console"
    in rumqttd::router::routing::[<] outgoing with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.621607Z DEBUG rumqttd::router::routing: Acks sent to device, acks_count: 1
    in rumqttd::router::routing::outgoing_ack with client_id: "console"
    in rumqttd::router::routing::[<] outgoing with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.621841Z TRACE rumqttd::router::scheduler: pause Ready -> Caughtup, tracker_id: "console"
    in rumqttd::router::routing::[<] outgoing with connection_id: 0
    in rumqttd::router::routing::run

  2024-11-30T13:51:32.622783Z  INFO rumqttd::server::broker: Listening for remote connections, config: "v4-1", listen_addr: "0.0.0.0:1883"

  2024-11-30T13:51:32.623221Z  INFO rumqttd::server::broker: Listening for remote connections, config: "ws-1", listen_addr: "0.0.0.0:8083"

  2024-11-30T13:51:32.623316Z  INFO rumqttd::server::broker: Listening for remote connections, config: "v5-1", listen_addr: "0.0.0.0:1884"

  2024-11-30T13:51:34.807830Z  INFO rumqttd::server::broker: accept, name: "v4-1", addr: 127.0.0.1:50809, count: 0, tenant: None

  2024-11-30T13:51:34.808238Z TRACE rumqttd::router::routing: Validating Client ID = test
    in rumqttd::router::routing::[>] incoming with connection_id: 0
    in rumqttd::router::routing::run

This is the part of the log that bugs me, I don't expect this 2 seconds delay.

  2024-11-30T13:51:32.622783Z  INFO rumqttd::server::broker: Listening for remote connections, config: "v4-1", listen_addr: "0.0.0.0:1883"

  2024-11-30T13:51:32.623221Z  INFO rumqttd::server::broker: Listening for remote connections, config: "ws-1", listen_addr: "0.0.0.0:8083"

  2024-11-30T13:51:32.623316Z  INFO rumqttd::server::broker: Listening for remote connections, config: "v5-1", listen_addr: "0.0.0.0:1884"

  2024-11-30T13:51:34.807830Z  INFO rumqttd::server::broker: accept, name: "v4-1", addr: 127.0.0.1:50809, count: 0, tenant: None

[wardru]

My apologies I forgot to mention a few details:

I tried running a mosquitto broker and connect my client to it, and it connected instantly.
I also tried to connect MQTT explorer to the broker, and it also connected instantly.

My conclusion is that the delay occurs only when a rumqttc client connects to a rumqttd client.