Paho MQTT Client (Javascript), Envoy, VerneMQ: debug delle disconnessioni

Di Maximilian Batz | 2019-09-08

Dopo aver distribuito picockpit sul mio server, è stato osservato un bug: il frontend web si disconnetteva a intervalli molto regolari.

Questo non era presente nell'ambiente di sviluppo locale. Gli utenti di picockpit hanno riportato lo stesso bug.

Ho fatto il debug oggi e ho applicato un hotfix. Si è scoperto che era un problema di tempistica.

TL;DR come risolvere questo problema

impostare un keepAliveInterval più breve per Paho. 60 secondi è il valore predefinito, ma con le latenze di rete questo porterà a questi timeout.

Ecco il mio codice per la connessione (dentro pcp-code.js che viene caricato dalla pagina web):

/* https://www.eclipse.org/paho/files/jsdoc/Paho.MQTT.Client.html */
funzione MQTTconnect_inner(params){
     mqtt = nuovo Paho.Client(params.uri, params.clientid); /* impostazione di parametri non richiesti poiché JS non permette di passare parametri posizionali nominati */
     mqtt.onConnectionLost = mqtt_onConnectionLost;
     mqtt.onMessageDelivered = mqtt_onMessageDelivered;
     mqtt.onMessageArrived = mqtt_onMessageArrived;
     mqtt.onConnected = mqtt_onConnect_proper;

    var opzioni = {
         timeout: 3, /* se la connessione non ha successo entro 3 secondi, si considera fallita */
         onSuccess: mqtt_onConnect_connect,
         onFailure: mqtt_onConnectFailure_connect,
         userName: params.userName,
         password: params.password,
         keepAliveInterval: 30,
         useSSL: true,
         ricollegare: falso,
         mqttVersion: 4
     };
     mqtt.connect(opzioni);
}

(riprodotto anche come immagine)

Fasi di debug

Timing

Mi sono seduto con il mio cellulare per cronometrare i timeout e vedere se c'era un modello.

Nella mia implementazione, Paho viene ricollegato dal codice JavaScript circostante ogni 10 secondi al timeout.

Vediamo il client Paho javascript MQTT perdere la connessione ogni minuto o ogni due minuti. Questa è già una forte indicazione che si tratta di una cosa sistematica, forse una disconnessione forzata da parte del server.

Console JavaScript

Il messaggio di errore che vedo nella console è:

WebSocket è già nello stato CLOSING o CLOSED.

In retrospettiva, questo è probabilmente Paho che cerca di inviare il PINGREQ ma fallisce solo per un paio di secondi o forse microsecondi, poiché il server ha disconnesso il socket.

NB: Per una maggiore compatibilità con i firewall aziendali, ecc. Eseguo Paho tramite websockets.

Verifica con altri browser

Ho visto questo problema con Chrome (il mio browser principale) e Firefox. Quindi non è dovuto a un problema di browser.

(Sono stato portato a credere che potrebbe essere a qualche problema di browser da questo sito web: https://github.com/socketio/socket.io/issues/3259)

Debug di VerneMQ

vedere anche:

Mostra client_id e mountpoint completi per evitare troncamenti:

vmq-admin session show -mountpoint -client_id

Eseguire una traccia:

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

Come vedete, otterrete una traccia di ciò che viene inviato al client e ricevuto dal client.

Avvio della traccia per 1 sessione esistente per il cliente "js.1567943187982KSWuLXb" con PID

[]

MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/000000007eaefc47/com.picockpit/sensors/$state/pi") con 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 (troncato)

Ho anche visto un PINGREQ() e PINGRESP(), mantenendo la sessione viva in questa traccia:

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

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

Ecco come appare la disconnessione:

MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/00000000327f9cbf/com.picockpit/sensors/$state/pi") con 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 (troncata)

Sessione di tracciamento per js.1567943187982KSWuLXb interrotta

Purtroppo c'è nessuna informazione che questo è dovuto ad un timeout in attesa di una pingreq() dal client.

Debug di Envoy

Vedi anche:

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

Poiché non c'erano informazioni che questo fosse dovuto a un timeout di pingreq, i sospetti sono caduti su envoy che si disconnetteva a causa di timeout (possibilmente gestendo i websockets in modo scorretto a causa di una mia mancata impostazione di alcune configurazioni).

La configurazione è stata comunque applicata correttamente:

upgrade_configs:

- tipo_di_aggiornamento: "websocket"

abilitato: vero

per il percorso corretto (/mqtt)

Non ci sono timeout a parte connect_timeout per i backend (che sono stati impostati su valori diversi, sicuramente non un minuto).

Per abilitare l'output di debug da envoy, dovete aggiungere una variabile d'ambiente al docker-compose.yaml:

ambiente:

livello di log: debug

come gli ultimi versi della strofa per l'inviato di servizio

Ecco cosa vedo come traccia:

':status', '101'

'connessione', 'aggiornamento'

'data', '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', 'envoy'

'aggiornamento', 'websocket'

'contenuto-lunghezza', '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][connessione] [source/common/network/connection_impl.cc:520] [C9] chiusura remota

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

[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:82] [C9] disconnessione. azzerare 1 richiesta in sospeso

[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:105] [C9] richiesta azzerata

[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() resetta il flusso

[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][connessione] [source/common/network/connection_impl.cc:101] [C8] chiusura data_to_write=0 type=2

[2019-09-08 12:09:37.191][26][debug][connessione] [source/common/network/connection_impl.cc:653] [C8] impostazione del timer di chiusura ritardata con timeout 1000 ms

[2019-09-08 12:09:37.191][26][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C9] client disconnesso, motivo del fallimento:

[2019-09-08 12:09:38.192][26][debug][connessione] [source/common/network/connection_impl.cc:642] [C8] attivato chiusura ritardata

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

[2019-09-08 12:09:38.192][26][debug][connessione] [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] aggiunta alla lista di pulizia

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

Questo coincide con la disconnessione sul client

Come potete vedere, questo è iniziato da

[C9] chiusura a distanza

Questo ancora una volta getta il sospetto su VerneMQ che disconnette il client a causa di un problema di timeout.

Paho Opzioni di temporizzazione

Una buona fonte per leggere su MQTT e keep-alives è Steve's Internet Guide:

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

Il client deve inviare pacchetti keepalive (PINGREQ), in assenza di altri pacchetti di controllo, ed è responsabile per l'intervallo tra i pacchetti che non supera il valore Keep Alive impostato sul broker.

Il client può inviare i pacchetti prima

Il passo successivo dell'indagine ha portato a guardare Paho e il keepalive. La mia preoccupazione iniziale era che Paho non inviasse le keepalive da solo, quindi avrei dovuto eseguire un ciclo e inviarle.

Questo, tuttavia, si è scoperto che non è vero - Paho gestisce effettivamente le keepalive da sola.

Ecco il codice sorgente di Paho MQTT Javascript:

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

La linea 703 e seguenti hanno il "Pinger".

definisce una funzione doTimeout, che a sua volta restituisce doPing

doPing è definito un po' più avanti, esegue il ping effettivo, e imposta un timeout, con this._keepAliveInterval.

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

Ormai sono abbastanza sicuro che il keepAliveInterval deve essere diminuito per Paho dai 60 secondi predefiniti. Probabilmente a causa delle latenze di rete, ciò che ha funzionato per me localmente non funziona più in remoto.

come possiamo impostare un intervallo di tempo diverso?

Documentazione Paho:

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

L'istanza del client Paho ha un metodo connect, che prende un oggetto come unico parametro.

L'oggetto ha diversi attributi, uno dei quali è il keepAliveInterval:

Ho impostato questo keepAliveInterval a 30 sec. Ecco l'attuale set di parametri che uso:

var opzioni = {
     timeout: 3, /* se la connessione non ha successo entro 3 secondi, si considera fallita */
     onSuccess: mqtt_onConnect_connect,
     onFailure: mqtt_onConnectFailure_connect,
     userName: params.userName,
     password: params.password,
     keepAliveInterval: 30,
     useSSL: true,
     ricollegare: falso,
     mqttVersion: 4
};
mqtt.connect(opzioni);

Con mqtt che è un'istanza del Paho MQTT Client.

Pubblicato in MQTT, PiCockpit, VerneMQ con tag debug, envoy, javascript, keepAliveInterval, mqtt, network, paho, PINGREQ, remote, timeout, timing, vernemq, websocket, websockets