search

AtherEnergy / rumqtt

Pure rust mqtt cilent
The Unlicense
202 stars 71 forks source link

disconnect if keepalive is 10 #157

Closed bbigras closed 5 years ago

bbigras commented 5 years ago

Maybe related to https://github.com/AtherEnergy/rumqtt/issues/76.

This code often disconnects after 15 secs but not every time.

rumqtt 3b5571a40275be65188a678c39d70b75e67a77d7 rustc 1.36.0-nightly (7c71bc320 2019-04-30)

use env_logger::Env;
use rumqtt::{MqttClient, MqttOptions, QoS};

use std::{thread, time::Duration};

fn main() {
    let env = Env::default().filter_or(
        "RUST_LOG",
        "test_rumqtt=debug,rumqtt=info,tokio_reactor=info,debug",
    );
    env_logger::init_from_env(env);

    let mqtt_options = MqttOptions::new("test-id-1", "127.0.0.1", 1883).set_keep_alive(10);
    let (mut mqtt_client, notifications) = MqttClient::start(mqtt_options).unwrap();

    thread::spawn(move || {
        mqtt_client
            .publish("hello/world", QoS::AtLeastOnce, true, "test")
            .unwrap();

        thread::sleep(Duration::from_secs(300));
    });

    for notification in notifications {
        println!("notification: {:?}", notification)
    }
}
[2019-06-13T18:56:35Z DEBUG tokio_reactor] adding I/O source: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Write for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z INFO  rumqtt::client::connection] Mqtt connect response = Some(Connack(Connack { session_present: false, code: Accepted }))
[2019-06-13T18:56:35Z INFO  rumqtt::client::connection] Mqtt connection successful!!
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG rumqtt::client::connection] Outgoing request = "topic = hello/world, qos = AtLeastOnce, pkid = Some(PacketIdentifier(1)), payload size = 4 bytes"
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG rumqtt::client::connection] Incoming packet = "Puback(PacketIdentifier(1))"
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:35Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:43Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:45Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:45Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:45Z DEBUG rumqtt::client::mqttstate] Ping = None. keep alive = 10,
            last incoming packet before 9 secs,
            last outgoing packet before 9 secs
[2019-06-13T18:56:45Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:45Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:45Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-13T18:56:50Z DEBUG rumqtt::client::mqttstate] Ping = Ping. keep alive = 10,
            last incoming packet before 15 secs,
            last outgoing packet before 5 secs
[2019-06-13T18:56:50Z DEBUG tokio_reactor] dropping I/O source: 0
$ docker run -it --rm -p 1883:1883 -p 9001:9001 eclipse-mosquitto
1560452193: mosquitto version 1.6.2 starting
1560452193: Config loaded from /mosquitto/config/mosquitto.conf.
1560452193: Opening ipv4 listen socket on port 1883.
1560452193: Opening ipv6 listen socket on port 1883.
1560452195: New connection from 172.17.0.1 on port 1883.
1560452195: New client connected from 172.17.0.1 as test-id-1 (p2, c1, k10).
1560452210: Client test-id-1 has exceeded timeout, disconnecting.
tekjar commented 5 years ago

Thanks for the report. There is a major refactor happening now. I'll verify this as soon as I'm done with it

bestouff commented 5 years ago

FWIW I'm using 60s with VerneMQ as a broker, and I have frequent disconnections because rumqtt "forgets" to ping sometimes (I often see 120s between pings).

tekjar commented 5 years ago

@bestouff @bbigras Can you verify if develop branch solved this issue?

bbigras commented 5 years ago

I still have the problem. It still doesn't happen every time, only sometime.

branch=develop 8e78893ecb6711d66ae20c58f207357c3d08f43f rustc 1.36.0-nightly (7c71bc320 2019-04-30)

[2019-06-28T13:31:39Z DEBUG tokio_reactor] adding I/O source: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Write for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z INFO  rumqtt::client::connection] Mqtt connect response = Some(Connack(Connack { session_present: false, code: Accepted }))
[2019-06-28T13:31:39Z INFO  rumqtt::client::connection] Mqtt connection successful!!
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG rumqtt::client::connection] Incoming packet = "Puback(PacketIdentifier(1))"
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:39Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:47Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:49Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:49Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:49Z DEBUG rumqtt::client::mqttstate] Ping = None. keep alive = 10,
            last incoming packet before 9 secs,
            last outgoing packet before 9 secs
[2019-06-28T13:31:49Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:49Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:49Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:31:54Z DEBUG rumqtt::client::mqttstate] Ping = Ping. keep alive = 10,
            last incoming packet before 15 secs,
            last outgoing packet before 5 secs
[2019-06-28T13:31:54Z DEBUG tokio_reactor] dropping I/O source: 0
[2019-06-28T13:31:54Z DEBUG rumqtt::client::connection] Eventloop stopped with error. NetworkStreamClosed
notification: Disconnection
[2019-06-28T13:32:04Z DEBUG tokio_reactor] adding I/O source: 0
[2019-06-28T13:32:04Z DEBUG tokio_reactor::registration] scheduling Write for: 0
[2019-06-28T13:32:04Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:32:04Z INFO  rumqtt::client::connection] Mqtt connect response = Some(Connack(Connack { session_present: false, code: Accepted }))
[2019-06-28T13:32:04Z INFO  rumqtt::client::connection] Mqtt connection successful!!
notification: Reconnection
[2019-06-28T13:32:04Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:32:04Z DEBUG tokio_reactor::registration] scheduling Read for: 0
[2019-06-28T13:32:04Z DEBUG tokio_reactor::registration] scheduling Read for: 0
$ docker run -it --rm -p 1883:1883 -p 9001:9001 eclipse-mosquitto
1561728680: mosquitto version 1.6.3 starting
1561728680: Config loaded from /mosquitto/config/mosquitto.conf.
1561728680: Opening ipv4 listen socket on port 1883.
1561728680: Opening ipv6 listen socket on port 1883.
1561728699: New connection from 172.17.0.1 on port 1883.
1561728699: New client connected from 172.17.0.1 as test-id-1 (p2, c1, k10).
1561728714: Client test-id-1 has exceeded timeout, disconnecting.
1561728724: New connection from 172.17.0.1 on port 1883.
1561728724: New client connected from 172.17.0.1 as test-id-1 (p2, c1, k10).
1561728726: Socket error on client test-id-1, disconnecting.
^C1561728727: mosquitto version 1.6.3 terminating
tekjar commented 5 years ago

Thanks for the report. This helped uncover a bug. I couldn't reproduce this with your example but some late publishes caused similar issue. I think the root problem is fixed and unit tests are in place. Want to give it a try? :)

bbigras commented 5 years ago

I don't seem able to reproduce the problem with branch=develop 5336f2d1126e10c807fe22263589f6e79ae95e82 :+1:

tekjar commented 5 years ago

Cool. I'll go ahead and close this. Feel free to reopen if this reoccurs

bestouff commented 5 years ago

Is there an official release where this bug is fixed ?

bestouff commented 5 years ago

Ping?

tekjar commented 5 years ago

Ah sorry. No release yet. I'll push to crates on monday

bestouff commented 5 years ago

Great thanks