MQTT problemen

[SaturnusDJ]

Description

Na een update van 3.2.0 naar 5.10.3, wat overigens prima leek te gaan...het volgende: In de log zie ik dat er elke 6-7 minuten een restart van DSMR backend is. Er is iets mis met MQTT. Foutmeldingen, en waarden komen niet meer regelmatig binnen in HA. Alleen de waarde van bij de herstart komt door.

[Home] › [MQTT] › Outgoing MQTT messages Daar staat een lijst van ~2-45. Zelfs als MQTT uitgeschakeld is. Leegmaken helpt niet, het vult aardig snel weer.

Mosquitto opnieuw gestart. Het topic weggegooid. DSMR Reader verschillende malen opnieuw gestart. De MQTT instellingen doorlopen en opnieuw opgeslagen.

In HA de MQTT instelling nog even op v5 gezet, dat is ook de versie waar de broker op draait, maar ook dat helpt niet.

Het is wellicht hetzelfde als https://github.com/dsmrreader/dsmr-reader/issues/1433.

DSMR-reader version

5.10.3

DSMR-reader platform

Docker (e.g. Xirixiz)

Debug info dump

Elke ~6 minuten:

DEBUG    broker       run                             100 | MQTT: Processing 20 message(s)
DEBUG    broker       run                             103 | MQTT: Publishing queued message (#14801535) for dsmr/reading/electricity_currently_delivered: 0.363
DEBUG    broker       on_log                          194 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m18), 'b'dsmr/reading/electricity_currently_delivered'', ... (5 bytes)
DEBUG    broker       on_disconnect                   180 | MQTT: (Paho on_disconnect) 7
WARNING  broker       on_disconnect                   183 | MQTT: --- Unexpected disconnect, re-connecting...
DEBUG    broker       on_log                          194 | MQTT: (Paho on_log) Sending CONNECT (u1, p1, wr0, wq0, wf0, c1, k60) client_id=b'dsmr_reader'
WARNING  broker       signal_reconnect                146 | MQTT: Client no longer connected. Signaling restart to reconnect...
ERROR    persistent_clients run                              42 | CLIENTS: Run error: MQTT: Client loop() failed, requesting restart...
WARNING  dsmr_backend _check_restart_required          49 | Detected backend restart required, stopping process...

[dennissiemensma]

Bedankt voor je melding. Je kunt in #1485 kijken via een tweede listener of, en hoe snel, DSMR-reader de queue met berichten verstuurt. En het is ook interessant om te kijken hoe snel je broker de berichten verwerkt, in de paar minuten dat ze wel aankomen. Het kan zijn dat DSMR-reader te traag bij je werkt met QoS 2 (gegarandeerde data overdracht, maar relatief traag), of dat de broker te traag is.

[dennissiemensma]

En debug logging aanzetten is ook een must, gezien je daarmee exact kan zien waar het versturen of acken op wacht (in DSMR-reader dan).

[dennissiemensma]

Ik bedoel overigens #1465, maar wellicht is die gelijk aan het originele issue waar die van afgetakt is.

[SaturnusDJ]

Bedankt voor de antwoorden! Een paar dagen verder alweer nu. Hopelijk dit weekend tijd voor, anders de volgende. Geef mij eventueel een trap als je voor die tijd niets gehoord hebt.

[SaturnusDJ]

Een eerste update:

WARNING  messages     queue_message                    24 | MQTT: Rejecting message for topic due to maximum queue size (5000)

En inderdaad. Ik zie er 5000 in de GUI. Op /admin/dsmr_mqtt/message/ selecteer ik alles, dan verschijnt de keuze om alle 5000 te selecteren, wat ik doe. Dan de action Delete selected Outgoing MQTT messages, Go. Hij laadt voor een seconde of 10 en vraagt om bevestiging. Ik druk op Yes, I am sure, en dan komt een witte pagina met: Bad Request (400). Per 100 lukt wel, maar liever niet haha.

Mogelijk is deze gerelateerd:

[warn] 309#309: *78 an upstream response is buffered to a temporary file /var/lib/nginx/tmp/proxy/7/00/0000000007 while reading upstream, client: 192.168.1.3, server: _, request: "POST /admin/dsmr_mqtt/message/ HTTP/1.1", upstream: "http://unix:///tmp/gunicorn--dsmr_webinterface.socket:/admin/dsmr_mqtt/message/", host: "DSMR", referrer: "http://DSMR/admin/dsmr_mqtt/message/"

Nog gekker: MQTT was niet enabled op /admin/dsmr_mqtt/mqttbrokersettings/. Waarom zouden er dan toch die MQTT berichten gemaakt worden en in een wachtrij gestopt?

Dus aangezet, geen verschil. Weer uitgezet, de 5000 zijn weg maar er stromen weer nieuwen binnen.

[dennissiemensma]

Het genereren van de MQTT berichten is bewust losgetrokken van het versturen. Dit is omdat er dan bij korte onderbrekingen met terugwerkende kracht alsnog alles verstuurd kan worden. Echter is het soms wat minder nuttig wanneer er helemaal niets verstuurd wordt. De instellingen voor de databronnen en het versturen naar de broker zijn dan ook los van elkaar, met een standaard max van 5000 zodat je database niet overvol raakt als je dit pas na een week zou merken.

Ik denk dat je met debug logging even moet kijken hoelang het gemiddeld duurt voordat een bericht verstuurd wordt.

Verder wordt de MQTT connectie uitgeschakeld bij een fout, maar dat is meer een gevolg. Zulke fouten zouden ook in de backend log moeten staan.

[dennissiemensma]

Het in bulk wipen van de queue kan overigens met: https://github.com/dsmrreader/dsmr-reader/issues/1643#issuecomment-1152522679

[dennissiemensma]

Mocht je nog meer hulp nodig hebben dan hoor ik het graag.

[SaturnusDJ]

Dit heeft veel te lang geduurd. Excuses, excuses. Veel gebeurd, en een klein deel daarin was het upgraden van de 15 jaar oude server waar Postgres en Mosquitto op draaien. Alles is waanzinnig snel nu met door de dag heen nog geen 1% CPU gebruik. DSMR Reader zelf draait op een Pi 3B+.

Ik schakelde vandaag MQTT weer in, en na een restart van DSMR Reader werden de 5000 berichten allemaal achter elkaar in hoge snelheid verstuurd. Dit was in een seconde of 10 klaar.

Vervolgens kwam er nu wel elke x minuten MQTT data binnen. Deze data was relatief verouderd vergeleken met de laatste metingen. Met debug logging aan zag ik dat de waarde van Backend process sleep lijkt te bepalen wanneer MQTT verstuurd. Die van 3 minuten naar 1 minuut gezet en de boel is meer up to date. Het lijkt er dus op dat er geen mega wachtrij meer ontstaat. Wat dit (oorspronkelijke) probleem opgelost heeft ben ik niet achter...

Jaren terug had ik https://github.com/dsmrreader/dsmr-reader/issues/862 aangevraagd met het idee om de load op de Pi 3B+ omlaag te brengen. Ik zie niet een verhoogde load nu die van 3 minuten naar 1 minuut is gegaan.

Wat is in deze laatste versie de betekenis van "backend process sleep"?

[dennissiemensma]

De backend sleep pauzeert alle achtergrond processen, inclusief MQTT.

[SaturnusDJ]

Dank. Dan zal het nu wel lopen. Nog steeds niet duidelijk waarom, helaas.