256dpi / arduino-mqtt

MQTT library for Arduino
MIT License
1.01k stars 232 forks source link

Client disconnecting [Terminated due to {shutdown,tcp_closed}] #248

Closed SMaxOwok closed 3 years ago

SMaxOwok commented 3 years ago

I'm having an issue where my client is disconnecting from my EMQX broker. I'm having trouble tracing this back to determine where the point of failure is that is causing the client to disconnect.

Looking through the EMQX logs, it seems like the client successfully subscribes, but disconnects before it acknowledges the SUBACK from the broker.

2021-05-19 04:14:06.780 [debug] [MQTT] RECV << ... >>
2021-05-19 04:14:06.780 [debug] [MQTT] RECV CONNECT(Q0, R0, D0, ClientId=sensor-15935941-7545-44f0-91ac-b810bf6c6f4f, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=10, Username=undefined, Password=undefined)
2021-05-19 04:14:06.782 [debug] <<"sensor-15935941-7545-44f0-91ac-b810bf6c6f4f">> [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2021-05-19 04:14:06.873 [debug] <<"sensor-15935941-7545-44f0-91ac-b810bf6c6f4f">> [MQTT] RECV << ... >>
2021-05-19 04:14:06.873 [debug] <<"sensor-15935941-7545-44f0-91ac-b810bf6c6f4f">> [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"sensors/15935941-7545-44f0-91ac-b810bf6c6f4f">>,#{nl => 0,qos => 0,rap => 0,rh => 0}}])
2021-05-19 04:14:06.874 [debug] <<"sensor-15935941-7545-44f0-91ac-b810bf6c6f4f">> [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[0])
2021-05-19 04:14:06.974 [debug] <<"sensor-15935941-7545-44f0-91ac-b810bf6c6f4f">> [MQTT] Terminated due to {shutdown,tcp_closed}

We cycle the device on/off in 20 minute intervals and it progresses through its steps with a simple state machine. This is how we're attempting to publish and connect as part of that. This does work most of the time, but often enough we see the issue with disconnecting.

bool connect() {
    bool connected = false;

    connected = client.connect(clientId);

    if (!connected) return false;

    Serial.println("[MQTTManager] Connected");
    Serial.print(">> clientId: ");
    Serial.println(clientId);

    Serial.println();
    Serial.println("[MQTTManager] Subscribing");
    bool subscribed = client.subscribe(topic);

    if (subscribed) {
        Serial.println("[MQTTManager] Subscribed");
        Serial.print(">> topic: ");
        Serial.println(topic);
    }

    return connected && subscribed;
}

bool publish(const String &topic, const String &payload) {
    if (!connect()) return false;

    Serial.println();
    Serial.println("[MQTTManager] Publishing");
    Serial.print(">> Topic: ");
    Serial.println(topic);
    Serial.print(">> Payload: ");
    Serial.println(payload);

    bool isPublished = client.publish(topic, payload, false, 2);

    if (!isPublished) {
        Serial.println();
        Serial.println("[MQTTManager] Publish failed");
        Serial.print(">> Error code ");
        Serial.println(client.lastError());
        Serial.print(">> Return code ");
        Serial.println(client.returnCode());
    }

    return isPublished;
}

Those debugging outputs look like this for a run where the client disconnects after subscription. Sometimes the error code is -1, but I assume that may be separate issue.

[MQTTManager] Connecting
[MQTTManager] Connected
>> clientId: sensor-15935941-7545-44f0-91ac-b810bf6c6f4f

[MQTTManager] Subscribing
[MQTTManager] Subscribed
>> topic: sensors/15935941-7545-44f0-91ac-b810bf6c6f4f

[MQTTManager] Publishing
>> Topic: readings
>> Payload: {"SensorId":"15935941-7545-44f0-91ac-b810bf6c6f4f","Light":43,"Moisture":30,"Temp":69.26,"Battery":81,"Signal":100}

[MQTTManager] Publish failed
>> Error code 0
>> Return code 0
TheRealDJ commented 3 years ago

What happens if you comment the subscribe call ... Does the publish work? Does the server still show Terminated due to {shutdown,tcp_closed}? Are you using a secure connection?

SMaxOwok commented 3 years ago

Same issue with or without trying to subscribe after connecting. Right now it's not a secure connection.

TheRealDJ commented 3 years ago

Do you have a client.loop() in your loop function? @256dpi Is a client.loop() call required to maintain an active connection?

SMaxOwok commented 3 years ago

As I understand it, client.loop() is only necessary for keep-alives if specified or reading incoming messages. That said, with or without client.loop() I get the same issue.

TheRealDJ commented 3 years ago

On ESP32 ... MQTT-ISSUE-248.ino (Masked mqtt.begin() IP_ADDRESS, user, pass)

/* https://github.com/256dpi/arduino-mqtt/issues/248 */

#include <WiFi.h>
#include <MQTT.h>

WiFiClient client;
MQTTClient mqtt(1024);

bool connected = false;

void setup() {
    delay(5000);
    Serial.begin(115200);
    Serial.println("Starting setup() ...");

    Serial.println("Device started. Starting WiFi ...");
    WiFi.setHostname("esp32-mqtt");
    while ( WiFi.status() != WL_CONNECTED ) {
        WiFi.begin();
        delay(1000);
    }
    Serial.print("WiFi started. IP: ");
    Serial.println(WiFi.localIP());

    Serial.println("Starting MQTT ... ");
    mqtt.begin("IP_ADDRESS", 1883, client);
    connected = mqtt.connect("mqtt-test", "user", "pass");
    if ( connected ) {
        Serial.println("MQTT Connected");
    } else {
        Serial.println("MQTT Not Connected");
    }

    Serial.println("setup() complete.");
}

void loop() {
    if ( connected ) {
        bool published = false;
        String message = String(millis());
        Serial.println("Publishing '" + message + "' to '/topic'");
        published = mqtt.publish("/topic", message);
        if ( published ) {
            Serial.println("MQTT Message Published Successfully");
        } else {
            Serial.println("FAILED to publish MQTT Message");
        }
    } else {
        Serial.println("MQTT Not Connected");
    }
    delay(5000);
}

Serial Output: (Masked CLIENT_IP)

Starting setup() ...
Device started. Starting WiFi ...
WiFi started. IP: CLIENT_IP
Starting MQTT ... 
MQTT Connected
setup() complete.
Publishing '6156' to '/topic'
MQTT Message Published Successfully
Publishing '11158' to '/topic'
MQTT Message Published Successfully
Publishing '16160' to '/topic'
MQTT Message Published Successfully
Publishing '21161' to '/topic'
MQTT Message Published Successfully
Publishing '26163' to '/topic'
MQTT Message Published Successfully
Publishing '31165' to '/topic'
MQTT Message Published Successfully
...

FYI: On ESP32, WiFi.begin() with no parameters uses the credentials last used on the ESP32. The code I had running on this device before this code supplied my network credentials.

256dpi commented 3 years ago

@TheRealDJ If you're only publishing and have no or a high keep alive you can omit client.loop(), otherwise you need to add it for the client to maintain the connection and handle incoming messages.

SMaxOwok commented 3 years ago

@256dpi Do you see any issues in how we're structuring things that might lead to this fragile connection?

TheRealDJ commented 3 years ago

I think we need to see more of your code. Also, what device are you trying to run this on?