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);   
}

afbeelding

(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.

afbeelding

In mijn implementatie wordt Paho opnieuw verbonden door omringende JavaScript code elke 10 seconden op timeout.

afbeelding

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

afbeelding

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:

Toon volledige client_id en mountpoint om truncatie te vermijden:

vmq-admin session show -mountpoint -client_id

afbeelding

Traceer het:

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

afbeelding

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

afbeelding

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]

[source/common/http/codec_client.cc:82] [C9] verbreek de verbinding. resetten van 1 in behandeling zijnde verzoeken

[2019-09-08 12:09:37.190][26][debug]

[source/common/http/codec_client.cc:105] [C9] verzoek reset

[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

afbeelding

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:

afbeelding

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.