Paho MQTT Client (Javascript), Envoy, VerneMQ: Fehlersuche bei Verbindungsabbrüchen

Von Maximilian Batz | 2019-09-08

Nachdem ich picockpit auf meinem Server installiert hatte, stellte ich einen Fehler fest: Das Web-Frontend brach in regelmäßigen Abständen ab.

In der lokalen Entwicklungsumgebung war dieser Fehler nicht aufgetreten. Benutzer von picockpit meldeten denselben Fehler.

Ich habe das Problem heute behoben und ein Hotfix angewendet. Es stellte sich heraus, dass es ein Zeitproblem war.

TL;DR wie man das beheben kann

ein kürzeres keepAliveIntervall für Paho einrichten. 60 Sekunden ist der Standardwert, aber bei Netzwerklatenzen führt dies zu diesen Zeitüberschreitungen.

Hier ist mein Code für die Verbindung (innerhalb der pcp-code.js, die von der Webseite geladen wird):

/* https://www.eclipse.org/paho/files/jsdoc/Paho.MQTT.Client.html */
Funktion MQTTconnect_inner(params){
     mqtt = new Paho.Client(params.uri, params.clientid); /* Einstellung nicht benötigter Parameter, da JS die Übergabe von benannten Positionsparametern nicht erlaubt */
     mqtt.onConnectionLost = mqtt_onConnectionLost;
     mqtt.onMessageDelivered = mqtt_onMessageDelivered;
     mqtt.onMessageArrived = mqtt_onMessageArrived;
     mqtt.onConnected = mqtt_onConnect_proper;

    var options = {
         timeout: 3, /* wenn die Verbindung innerhalb von 3 Sekunden nicht erfolgreich ist, gilt sie als fehlgeschlagen */
         onSuccess: mqtt_onConnect_connect,
         onFailure: mqtt_onConnectFailure_connect,
         benutzername: params.benutzername,
         Passwort: params.password,
         keepAliveInterval: 30,
         useSSL: wahr,
         Wiederverbinden: false,
         mqttVersion: 4
     };
     mqtt.connect(options);
}

(auch als Bild reproduziert)

Schritte zur Fehlersuche

Timing

Ich habe mich mit meinem Handy hingesetzt, um die Zeitüberschreitungen zu messen und zu sehen, ob es da ein Muster gibt.

In meiner Implementierung wird Paho durch umgebenden JavaScript-Code alle 10 Sekunden bei Zeitüberschreitung neu verbunden.

Wir sehen, dass der Paho javascript MQTT-Client die Verbindung jede Minute oder alle zwei Minuten unterbricht. Dies ist bereits ein starkes Indiz dafür, dass dies systematisch geschieht, möglicherweise eine erzwungene Trennung durch den Server.

JavaScript-Konsole

Die Fehlermeldung, die ich in der Konsole sehe, lautet

WebSocket befindet sich bereits im Zustand CLOSING oder CLOSED.

Im Nachhinein betrachtet, ist dies möglicherweise der Versuch von Paho, die PINGREQ zu senden, der aber um ein paar Sekunden oder möglicherweise Mikrosekunden scheitert, da der Server die Verbindung zum Socket getrennt hat.

NB: Für eine bessere Kompatibilität mit Firmen-Firewalls usw. Ich lasse Paho über Websockets laufen.

Überprüfung mit anderen Browsern

Ich habe dieses Problem mit Chrome (meinem Hauptbrowser) und Firefox gesehen. Es ist also nicht auf ein Browserproblem zurückzuführen.

(Diese Website hat mich zu der Annahme verleitet, dass es sich um ein Browserproblem handeln könnte: https://github.com/socketio/socket.io/issues/3259)

Fehlersuche bei VerneMQ

siehe auch:

Zeigen Sie die vollständige client_id und den Einhängepunkt an, um ein Abschneiden zu vermeiden:

vmq-admin session show -mountpoint -client_id

Führen Sie eine Verfolgung durch:

vmq-admin trace client client-id=js.1567943187982KSWuLXb -mountpoint=5cc72b97a6b76f00013d35d2

Wie Sie sehen, können Sie nachvollziehen, was an den Client gesendet und vom Client empfangen wird.

Starten der Ablaufverfolgung für 1 bestehende Sitzung für den Client "js.1567943187982KSWuLXb" mit PIDs

[]

MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/000000007eaefc47/com.picockpit/sensors/$state/pi") mit payload:

{"wlan_signal_info": "Link Quality=61/70 Signal level=-49 dBm", "cpu_load": 1.4, "net_io_bytes_received": 798582943, "root_partition_used": 2028572672, "net_io_bytes_sent": 1482989984, "soc_temperatu (truncated)

Ich habe auch ein PINGREQ() und PINGRESP() gesehen, die die Sitzung in diesem Trace am Leben erhalten:

MQTT RECV: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PINGREQ()

MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PINGRESP()

So sieht die Unterbrechung der Verbindung aus:

MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/00000000327f9cbf/com.picockpit/sensors/$state/pi") mit payload:

{"wlan_signal_info": "Link Quality=68/70 Signal level=-42 dBm", "ram_total_bytes": 969392128, "$uuid": “928ca964-d22e-11e9-9e22-dca632007438”, “disk_io_bytes_written”: 619947008, "root_partition_tota (truncated)

Trace-Sitzung für js.1567943187982KSWuLXb beendet

Leider gibt es keine Information dass dies auf eine Zeitüberschreitung beim Warten auf ein pingreq() vom Client zurückzuführen ist.

Fehlersuche in Envoy

Siehe auch:

https://pi3g.com/2019/05/18/envoy-docker-and-websockets-debugging-and-configuration/

Da es keine Informationen gab, dass dies auf einen Pingreq-Timeout zurückzuführen ist, fiel der Verdacht auf envoy, das die Verbindung aufgrund von Timeouts abbricht (möglicherweise werden Websockets falsch behandelt, weil ich einige Einstellungen nicht richtig vorgenommen habe).

Die Konfiguration wurde jedoch ordnungsgemäß angewendet:

upgrade_configs:

- upgrade_type: "websocket"

aktiviert: true

für den richtigen Pfad (/mqtt)

Es gibt keine Timeouts außer connect_timeout für die Backends (die auf unterschiedliche Werte gesetzt wurden, sicherlich nicht eine Minute).

Um die Debug-Ausgabe von envoy zu aktivieren, müssen Sie eine Umgebungsvariable in die Datei docker-compose.yaml aufnehmen:

Umwelt:

Loglevel: Debug

wie die letzten Zeilen in der Strophe für den Dienstgesandten

Ich sehe Folgendes als Spur:

':status', '101'

Verbindung', 'Upgrade'

date', 'Sun, 08 Sep 2019 12:08:36 GMT'

sec-websocket-accept', 'mWAEi6p3RBFflHkNbxTMbnhaG4I='

sec-websocket-extensions', 'permessage-deflate; client_max_window_bits=15'

sec-websocket-protocol', 'mqtt'

'Server', 'Gesandter'

Upgrade', 'Websocket'

Inhalt-Länge', '0'

[2019-09-08 12:08:38.757][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:08:43.760][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:08:48.755][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:08:53.759][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:08:58.762][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:03.762][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:08.762][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:13.765][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:18.766][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:23.766][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:28.765][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:33.766][1][debug][main] [source/server/server.cc:170] flushing stats

[2019-09-08 12:09:37.190][26][debug][connection] [source/common/network/connection_impl.cc:520] [C9] remote Close

[2019-09-08 12:09:37.190][26][debug][connection] [source/common/network/connection_impl.cc:190] [C9] closing socket: 0

[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:82] [C9] disconnect. 1 ausstehende Anfragen zurücksetzen

[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:105] [C9] Anfrage zurückgesetzt

[2019-09-08 12:09:37.190][26][debug][router] [source/common/router/router.cc:868] [C8][S10834556124828578161] upstream reset: reset reason connection termination

[2019-09-08 12:09:37.190][26][debug][http] [source/common/http/conn_manager_impl.cc:187] [C8][S10834556124828578161] doEndStream() setzt Stream zurück

[2019-09-08 12:09:37.191][26][debug][http] [source/common/http/conn_manager_impl.cc:1596] [C8][S10834556124828578161] stream reset

[2019-09-08 12:09:37.191][26][debug][connection] [source/common/network/connection_impl.cc:101] [C8] closing data_to_write=0 type=2

[2019-09-08 12:09:37.191][26][debug][connection] [source/common/network/connection_impl.cc:653] [C8] Einstellung eines verzögerten Schließtimers mit Timeout 1000 ms

[2019-09-08 12:09:37.191][26][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C9] client disconnected, failure reason:

[2019-09-08 12:09:38.192][26][debug][connection] [source/common/network/connection_impl.cc:642] [C8] triggered delayed close

[2019-09-08 12:09:38.192][26][debug][connection] [source/common/network/connection_impl.cc:190] [C8] closing socket: 1

[2019-09-08 12:09:38.192][26][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:270] [C8] SSL shutdown: rc=0

[2019-09-08 12:09:38.192][26][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:201] [C8]

[2019-09-08 12:09:38.193][26][debug][main] [source/server/connection_handler_impl.cc:80] [C8] Hinzufügen zur Bereinigungsliste

[2019-09-08 12:09:38.767][1][debug][main] [source/server/server.cc:170] flushing stats

Dies fällt mit der Trennung der Verbindung auf dem Client zusammen

Wie Sie sehen können, wird dies eingeleitet durch

[C9] ferngesteuert Schließen

Dies wirft wiederum den Verdacht zurück, dass VerneMQ die Verbindung zum Client aufgrund eines Timeout-Problems trennt.

Paho Timing-Optionen

Eine gute Quelle für Informationen über MQTT und Keep-Alives ist Steve's Internet Guide:

http://www.steves-internet-guide.com/mqtt-keep-alive-by-example/

Der Client muss Keepalive-Pakete senden (PINGREQ), wenn keine anderen Kontrollpakete vorhanden sind, und ist verantwortlich für für das Intervall zwischen den Paketen, das den im Broker eingestellten Keep-Alive-Wert nicht überschreitet.

Der Client kann die Pakete früher senden

Der nächste Schritt der Untersuchung führte dazu, Paho und das Keepalive zu untersuchen. Meine anfängliche Sorge war, dass Paho von sich aus keine Keepalives senden würde, so dass ich eine Schleife laufen lassen und sie senden müsste.

Es stellte sich jedoch heraus, dass dies nicht der Fall war - Paho verwaltet die Keepalives selbst.

Hier ist der Quellcode von Paho MQTT Javascript:

https://github.com/eclipse/paho.mqtt.javascript/blob/master/src/paho-mqtt.js

Zeile 703 und folgende haben den "Pinger".

Sie definiert eine doTimeout-Funktion, die wiederum doPing zurückgibt.

doPing wird etwas weiter unten definiert, es führt den eigentlichen Ping aus und setzt ein Timeout mit this._keepAliveInterval.

this._client.socket.send(pingReq);
this.timeout = setTimeout(doTimeout(this), this._keepAliveInterval);

Inzwischen bin ich mir ziemlich sicher, dass das keepAliveInterval für Paho von den standardmäßigen 60 Sekunden herabgesetzt werden muss. Möglicherweise aufgrund von Netzwerklatenzen funktioniert das, was bei mir lokal funktionierte, aus der Ferne nicht mehr.

Wie können wir ein anderes Zeitintervall einstellen?

Paho-Dokumentation:

https://www.eclipse.org/paho/files/jsdoc/Paho.MQTT.Client.html

Die Paho-Client-Instanz hat eine Methode connect, die ein Objekt als einzigen Parameter annimmt.

Das Objekt hat verschiedene Attribute, eines davon ist das keepAliveInterval:

Ich setze dieses keepAliveInterval auf 30 Sekunden. Hier ist der aktuelle Satz von Parametern, die ich verwende:

var options = {
     timeout: 3, /* wenn die Verbindung innerhalb von 3 Sekunden nicht erfolgreich ist, gilt sie als fehlgeschlagen */
     onSuccess: mqtt_onConnect_connect,
     onFailure: mqtt_onConnectFailure_connect,
     benutzername: params.benutzername,
     Passwort: params.password,
     keepAliveInterval: 30,
     useSSL: wahr,
     Wiederverbinden: false,
     mqttVersion: 4
};
mqtt.connect(options);

Dabei ist mqtt eine Instanz des Paho MQTT Client.

Geposted in MQTT, PiCockpit, VerneMQ abgelegt unter debug, envoy, javascript, keepAliveInterval, mqtt, network, paho, PINGREQ, remote, timeout, timing, vernemq, websocket, websockets