Paho MQTT-client (Javascript), Envoy, VerneMQ: debuggen van verbroken verbindingen
Na het installeren van picockpit op mijn server, werd een bug waargenomen: de web frontend verbrak de verbinding met zeer regelmatige tussenpozen.
Dit was niet aanwezig op de lokale ontwikkelomgeving. Gebruikers van picockpit meldden dezelfde bug.
Ik heb het vandaag gedebugged, en een hotfix toegepast. Het blijkt dat het een timing probleem was.
TL;DR hoe dit op te lossen
stel een kortere keepAliveInterval in voor Paho. 60 seconden is de standaard, maar met netwerk latenties zal dit leiden tot deze timeouts.
Hier is mijn code voor de verbinding (in pcp-code.js die geladen wordt door de webpagina):
/* https://www.eclipse.org/paho/files/jsdoc/Paho.MQTT.Client.html */
functie MQTTconnect_inner(params){
mqtt = new Paho.Client(params.uri, params.clientid); /* het instellen van niet vereiste parameters aangezien JS niet toestaat om benoemde positionele parameters door te geven */
mqtt.onConnectionLost = mqtt_onConnectionLost;
mqtt.onMessageDelivered = mqtt_onMessageDelivered;
mqtt.onMessageArrived = mqtt_onMessageArrived;
mqtt.onConnected = mqtt_onConnect_proper;var options = {
timeout: 3, /* als de verbinding niet binnen 3 seconden succesvol is, wordt deze geacht te zijn mislukt */
onSuccess: mqtt_onConnect_connect,
onFailure: mqtt_onConnectFailure_connect,
userName: params.userName,
wachtwoord: params.wachtwoord,
keepAliveInterval: 30,
useSSL: true,
reconnect: false,
mqttVersion: 4
};
mqtt.connect(options);
}
(ook als afbeelding weergegeven)
Het debuggen van stappen
Timing
Ik ging zitten met mijn gsm om de time-outs te timen, en te zien of er een patroon in zat.
In mijn implementatie wordt Paho opnieuw verbonden door omringende JavaScript code elke 10 seconden op timeout.
We zien dat de Paho javascript MQTT client elke minuut of elke twee minuten de verbinding verliest. Dit is al een sterke aanwijzing dat dit systematisch is, mogelijk een gedwongen verbreking van de verbinding door de server.
JavaScript-console
De foutmelding die ik zie in de console is:
WebSocket is al in de status CLOSING of CLOSED.
Achteraf gezien is dit mogelijk Paho die probeert de PINGREQ te versturen, maar faalt met slechts een paar seconden of mogelijk microseconden, omdat de server de socket heeft verbroken.
NB: Voor superieure compatibiliteit met bedrijfsfirewalls, enz. Ik run Paho via websockets.
Verificatie met andere browser
Ik heb dit probleem gezien met Chrome (mijn hoofdbrowser) en Firefox. Het is dus niet te wijten aan een browserprobleem.
(Ik werd er door deze website toe gebracht te geloven dat het misschien aan een browserprobleem lag: https://github.com/socketio/socket.io/issues/3259)
Debuggen van VerneMQ
zie ook:
- https://pi3g.com/2019/08/08/vernemq-how-to-disconnect-clients-forceably-per-command-line/
- https://docs.vernemq.com/administration/managing-sessions
Toon volledige client_id en mountpoint om truncatie te vermijden:
vmq-admin session show -mountpoint -client_id
Traceer het:
vmq-admin trace client-id=js.1567943187982KSWuLXb -mountpoint=5cc72b97a6b76f00013d35d2
Zoals u ziet, krijgt u een spoor van wat naar de client wordt gestuurd en van de client wordt ontvangen.
Start trace voor 1 bestaande sessies voor client "js.1567943187982KSWuLXb" met PIDs
[]
MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/000000007eaefc47/com.picockpit/sensors/$state/pi") met 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 (afgekapt)
Ik zag ook een PINGREQ() en PINGRESP(), die de sessie in leven houden in dit spoor:
MQTT RECV: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PINGREQ()
MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PINGRESP()
Hier is hoe de ontkoppeling eruit ziet:
MQTT SEND: MP: "5cc72b97a6b76f00013d35d2" CID: "js.1567943187982KSWuLXb" PUBLISH(d0, q0, r0, m0, "pi/00000000327f9cbf/com.picockpit/sensors/$state/pi") met 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 (afgekapt)
Traceer sessie voor js.1567943187982KSWuLXb gestopt
Helaas is er geen informatie dat dit te wijten is aan een time-out wachtend op een pingreq() van de client.
Debuggen van Envoy
Zie ook:
Aangezien er geen informatie was dat dit te wijten is aan een pingreq timeout, viel de verdenking op envoy die de verbinding verbrak door timeouts (mogelijk door websockets verkeerd af te handelen doordat ik sommige configuraties niet goed had ingesteld).
De configuratie werd echter correct toegepast:
upgrade_configs:
- upgrade_type: "websocket"
ingeschakeld: waar
voor het juiste pad (/mqtt)
Er zijn geen timeouts behalve connect_timeout voor de backends (die waren ingesteld op verschillende waarden, zeker geen minuut).
Om debug output van envoy in te schakelen, moet je een omgevingsvariabele toevoegen aan de docker-compose.yaml:
omgeving:
loglevel: debug
als de laatste regels in de strofe voor de dienst gezant
Dit is wat ik zie als sporen:
':status', '101'
"verbinding", "upgrade
"datum", "zon, 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", "afgezant
"upgrade", "websocket
"inhoud-lengte", "0
[2019-09-08 12:08:38.757][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:08:43.760][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:08:48.755][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:08:53.759][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:08:58.762][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:03.762][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:08.762][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:13.765][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:18.766][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:23.766][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:28.765][1][debug][main] [source/server/server.cc:170] flushen stats
[2019-09-08 12:09:33.766][1][debug][main] [source/server/server.cc:170] flushen 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] socket sluiten: 0
[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:82] [C9] verbreken. resetten 1 in behandeling zijnde verzoeken
[2019-09-08 12:09:37.190][26][debug][client] [source/common/http/codec_client.cc:105] [C9] verzoek gereset
[2019-09-08 12:09:37.190][26][debug][router] [source/common/router/router.cc:868] [C8][S10834556124828578161] upstream reset: reset reden verbindingsbeëindiging
[2019-09-08 12:09:37.190][26][debug][http] [source/common/http/conn_manager_impl.cc:187] [C8][S10834556124828578161] doEndStream() resetten stream
[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] sluit data_to_write=0 type=2
[2019-09-08 12:09:37.191][26][debug][connection] [source/common/network/connection_impl.cc:653] [C8] instelling delayed close timer met 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] socket sluiten: 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] toevoegend aan opruimlijst
[2019-09-08 12:09:38.767][1][debug][main] [source/server/server.cc:170] flushen stats
Dit valt samen met het verbreken van de verbinding op de cliënt
Zoals u kunt zien, wordt dit in gang gezet door
[C9] op afstand sluiten
Dit werpt weer argwaan op als VerneMQ de verbinding met de client verbreekt vanwege een timeout probleem.
Paho Timing opties
Een goede bron om over MQTT en keep-alives te lezen is Steve's Internet Gids:
De client moet keepalive pakketten sturen (PINGREQ), bij afwezigheid van andere controlepakketten, en is verantwoordelijk voor het interval tussen de pakketten dat de "keep alive"-waarde die op de makelaar is ingesteld niet overschrijdt.
De cliënt kan de pakketten eerder verzenden
De volgende stap in het onderzoek leidde tot het bekijken van Paho en de keepalive. Mijn aanvankelijke zorg was dat Paho zelf geen keepalives zou sturen, zodat ik een lus zou moeten draaien en ze zou moeten sturen.
Dit bleek echter niet waar te zijn - Paho handelt de keepalives zelf af.
Hier is de broncode van Paho MQTT Javascript:
lijn 703 en volgende hebben de "Pinger".
het definieert een doTimeout functie, die op zijn beurt doPing teruggeeft
doPing wordt iets verderop gedefinieerd, het voert de eigenlijke ping uit, en stelt een timeout in, met this._keepAliveInterval.
deze._client.socket.send(pingReq);
this.timeout = setTimeout(doTimeout(this), this._keepAliveInterval);
Ik ben er inmiddels vrij zeker van dat de keepAliveInterval voor Paho moet worden verlaagd van de standaard 60 seconden. Mogelijk als gevolg van netwerkvertragingen, werkt wat voor mij lokaal werkte niet meer op afstand.
hoe kunnen we een ander tijdsinterval instellen?
Paho documentatie:
De Paho-client instantie heeft een methode connect, die een object als enige parameter neemt.
Het object heeft verschillende attributen, waarvan er één het keepAliveInterval is:
Ik stel deze keepAliveInterval in op 30 sec. Hier is de huidige set van parameters die ik gebruik:
var options = {
timeout: 3, /* als de verbinding niet binnen 3 seconden succesvol is, wordt deze geacht te zijn mislukt */
onSuccess: mqtt_onConnect_connect,
onFailure: mqtt_onConnectFailure_connect,
userName: params.userName,
wachtwoord: params.wachtwoord,
keepAliveInterval: 30,
useSSL: true,
reconnect: false,
mqttVersion: 4
};
mqtt.connect(options);
Met mqtt wordt een instantie van de Paho MQTT Client bedoeld.
Nederlands (Formeel) 
English 
Deutsch (Sie) 
Français 
Español 
Italiano 
Português 
简体中文