Paho MQTT Client (Javascript), Envoy, VerneMQ : débogage des déconnexions
Après avoir déployé picockpit sur mon serveur, un bug a été observé : le frontend web se déconnectait à intervalles très réguliers.
Ce problème n'était pas présent dans l'environnement de développement local. Les utilisateurs de picockpit ont signalé le même bogue.
Je l'ai débogué aujourd'hui et j'ai appliqué un correctif. Il s'avère que c'était un problème de timing.
TL;DR comment résoudre ce problème
configurer un keepAliveInterval plus court pour Paho. La valeur par défaut est de 60 secondes, mais avec les latences du réseau, cela entraînera ces délais d'attente.
Voici mon code pour la connexion (dans pcp-code.js qui est chargé par la page web) :
/* https://www.eclipse.org/paho/files/jsdoc/Paho.MQTT.Client.html */
function MQTTconnect_inner(params){
mqtt = new Paho.Client(params.uri, params.clientid) ; /* réglage des paramètres non requis car JS ne permet pas de passer des paramètres positionnels nommés */
mqtt.onConnectionLost = mqtt_onConnectionLost ;
mqtt.onMessageDelivered = mqtt_onMessageDelivered ;
mqtt.onMessageArrived = mqtt_onMessageArrived ;
mqtt.onConnected = mqtt_onConnect_proper ;var options = {
timeout : 3, /* si la connexion ne réussit pas dans les 3 secondes, elle est considérée comme ayant échoué */.
onSuccess : mqtt_onConnect_connect,
onFailure : mqtt_onConnectFailure_connect,
nom d'utilisateur : params.userName,
mot de passe : params.password,
keepAliveInterval : 30,
useSSL : true,
reconnect : false,
mqttVersion : 4
};
mqtt.connect(options) ;
}
(reproduit également en image)
Étapes de débogage
Timing
Je me suis assis avec mon téléphone portable pour chronométrer les temps d'arrêt, et voir s'il y avait un modèle.
Dans mon implémentation, Paho est reconnecté par le code JavaScript environnant toutes les 10 secondes sur le timeout.
Nous voyons le client MQTT Javascript de Paho perdre la connexion toutes les minutes ou toutes les deux minutes. C'est déjà une forte indication que c'est systématique, peut-être une déconnexion forcée par le serveur.
Console JavaScript
Le message d'erreur que je vois dans la console est le suivant :
La WebSocket est déjà dans l'état CLOSING ou CLOSED.
En rétrospective, il est possible que Paho essaie d'envoyer le PINGREQ mais échoue de quelques secondes ou microsecondes, car le serveur a déconnecté le socket.
NB : Pour une meilleure compatibilité avec les firewalls des entreprises, etc. j'exécute Paho via des websockets.
Vérification avec un autre navigateur
J'ai constaté ce problème avec Chrome (mon navigateur principal) et Firefox. Il n'est donc pas dû à un problème de navigateur.
(J'ai été amené à penser que cela pouvait être dû à des problèmes de navigateur par ce site web : https://github.com/socketio/socket.io/issues/3259)
Débogage de VerneMQ
voir aussi :
- https://pi3g.com/2019/08/08/vernemq-how-to-disconnect-clients-forceably-per-command-line/
- https://docs.vernemq.com/administration/managing-sessions
Afficher le nom complet du client et le point de montage pour éviter la troncature :
vmq-admin session show -mountpoint -client_id
Exécutez une trace :
vmq-admin trace client client-id=js.1567943187982KSWuLXb -mountpoint=5cc72b97a6b76f00013d35d2
Comme vous le voyez, vous obtiendrez une trace de ce qui est envoyé au client et reçu du client.
Démarrage de la trace pour 1 session existante pour le client "js.1567943187982KSWuLXb" avec PIDs
[]
MQTT SEND : MP : "5cc72b97a6b76f00013d35d2" CID : "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/000000007eaefc47/com.picockpit/sensors/$state/pi") avec charge utile :
{"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)
J'ai également vu un PINGREQ() et un PINGRESP(), maintenant la session en vie dans cette trace :
MQTT RECV : MP : "5cc72b97a6b76f00013d35d2" CID : "js.1567943187982KSWuLXb" PINGREQ()
MQTT SEND : MP : "5cc72b97a6b76f00013d35d2" CID : "js.1567943187982KSWuLXb" PINGRESP()
Voici à quoi ressemble la déconnexion :
MQTT SEND : MP : "5cc72b97a6b76f00013d35d2" CID : "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/00000000327f9cbf/com.picockpit/sensors/$state/pi") avec charge utile :
{"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 session pour js.1567943187982KSWuLXb arrêté
Malheureusement, il y a aucune information que cela est dû à un timeout en attente d'un pingreq() du client.
Déboguer Envoy
Voir aussi :
Comme il n'y avait pas d'information sur le fait que cela soit dû à un dépassement de temps de pingreq, les soupçons se sont portés sur le fait qu'envoy se déconnecte à cause de dépassements de temps (peut-être en gérant les websockets de manière incorrecte parce que je n'ai pas configuré correctement).
La configuration a toutefois été appliquée correctement :
upgrade_configs :
- upgrade_type : "websocket"
activé : vrai
pour le chemin correct (/mqtt)
Il n'y a pas de délais d'attente à part connect_timeout pour les backends (qui ont été réglés sur des valeurs différentes, sûrement pas une minute).
Pour activer la sortie de débogage d'envoy, vous devez ajouter une variable d'environnement au fichier docker-compose.yaml :
l'environnement :
loglevel : debug
comme les dernières lignes de la strophe pour l'envoyé de service
Voici ce que je vois comme trace :
':status', '101'
connexion", "mise à jour".
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-extensions'.
sec-websocket-protocol, mqtt
"serveur", "envoyé
mise à jour, websocket
content-length, 0
[2019-09-08 12:08:38.757][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:08:43.760][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:08:48.755][1][debug][main] [source/server/server.cc:170] vidage des statistiques
[2019-09-08 12:08:53.759][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:08:58.762][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:03.762][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:08.762][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:13.765][1][debug][main] [source/server/server.cc:170] vidage des statistiques
[2019-09-08 12:09:18.766][1][debug][main] [source/server/server.cc:170] vidage des statistiques
[2019-09-08 12:09:23.766][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:28.765][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:33.766][1][debug][main] [source/server/server.cc:170] vidange des statistiques
[2019-09-08 12:09:37.190][26][debug][connexion] [source/common/network/connection_impl.cc:520] [C9] Fermer à distance
[2019-09-08 12:09:37.190][26][debug][connexion] [source/common/network/connection_impl.cc:190] [C9] fermeture de la socket : 0
[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:82] [C9] disconnect. resetting 1 pending requests
[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:105] [C9] request reset
[2019-09-08 12:09:37.190][26][debug][router] [source/common/router/router.cc:868] [C8][S10834556124828578161] réinitialisation amont : raison de la réinitialisation de la fin de la connexion.
[2019-09-08 12:09:37.190][26][debug][http] [source/common/http/conn_manager_impl.cc:187] [C8][S10834556124828578161] doEndStream() réinitialisation du flux
[2019-09-08 12:09:37.191][26][debug][http] [source/common/http/conn_manager_impl.cc:1596] [C8][S10834556124828578161] réinitialisation du flux
[2019-09-08 12:09:37.191][26][debug][connexion] [source/common/network/connection_impl.cc:101] [C8] fermeture data_to_write=0 type=2
[2019-09-08 12:09:37.191][26][debug][connexion] [source/common/network/connection_impl.cc:653] [C8] mise en place d'une minuterie de fermeture différée avec un délai d'attente de 1 000 ms.
[2019-09-08 12:09:37.191][26][debug][pool] [source/common/http/http1/conn_pool.cc:129] [C9] client déconnecté, raison de l'échec :
[2019-09-08 12:09:38.192][26][debug][connexion] [source/common/network/connection_impl.cc:642] [C8] fermeture différée déclenchée
[2019-09-08 12:09:38.192][26][debug][connexion] [source/common/network/connection_impl.cc:190] [C8] fermeture de la socket : 1
[2019-09-08 12:09:38.192][26][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:270] [C8] Arrêt du SSL : 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] ajout à la liste de nettoyage
[2019-09-08 12:09:38.767][1][debug][main] [source/server/server.cc:170] vidange des statistiques
Cela coïncide avec la déconnexion sur le client.
Comme vous pouvez le voir, ceci est initié par
[C9] Fermer à distance
Cela jette à nouveau le soupçon sur VerneMQ qui déconnecte le client en raison d'un problème de timeout.
Options d'horaires de Paho
Une bonne source de lecture sur MQTT et les keep-alives est le Steve's Internet Guide :
Le client doit envoyer des paquets keepalive (PINGREQ), en l'absence d'autres paquets de contrôle, et est responsable pour l'intervalle entre les paquets ne dépassant pas la valeur Keep Alive définie sur le broker.
Le client peut envoyer les paquets plus tôt
L'étape suivante de l'enquête a consisté à examiner Paho et le keepalive. Ma préoccupation initiale était que Paho n'enverrait pas de keepalive par lui-même, de sorte que je devrais exécuter une boucle et les envoyer.
Cependant, il s'est avéré que ce n'était pas le cas - Paho gère lui-même les keepalives.
Voici le code source de Paho MQTT Javascript :
Les lignes 703 et suivantes ont le "Pinger".
il définit une fonction doTimeout, qui à son tour renvoie doPing
doPing est défini un peu plus loin, il exécute le ping réel, et met en place un délai d'attente, avec this._keepAliveInterval.
this._client.socket.send(pingReq) ;
this.timeout = setTimeout(doTimeout(this), this._keepAliveInterval) ;
À présent, je suis presque certain que l'intervalle keepAliveInterval doit être réduit pour Paho par rapport aux 60 secondes par défaut. Peut-être à cause des latences du réseau, ce qui fonctionnait pour moi localement ne fonctionne plus à distance.
comment configurer un intervalle de temps différent ?
Documentation de Paho :
L'instance du client Paho possède une méthode connect, qui prend un objet comme unique paramètre.
L'objet possède différents attributs, l'un d'entre eux étant le keepAliveInterval :
Je fixe ce keepAliveInterval à 30 secondes. Voici l'ensemble des paramètres que j'utilise actuellement :
var options = {
timeout : 3, /* si la connexion ne réussit pas dans les 3 secondes, elle est considérée comme ayant échoué */.
onSuccess : mqtt_onConnect_connect,
onFailure : mqtt_onConnectFailure_connect,
nom d'utilisateur : params.userName,
mot de passe : params.password,
keepAliveInterval : 30,
useSSL : true,
reconnect : false,
mqttVersion : 4
};
mqtt.connect(options) ;
Avec mqtt étant une instance du client MQTT de Paho.
Français 
English 
Deutsch (Sie) 
Español 
Italiano 
Português 
Nederlands (Formeel) 
简体中文