Cache voor MQTT-berichten kunnen uitschakelen

[Janoz-NL]

Description

Ik laat mijn dsmr-reader zijn gegevens via MQTT doorsturen naar Home Assistant.

Na een week lijkt het alsof er geen MQTT berichten meer doorgestuurd worden. De grafieken in HA houden abrupt op. In DSMR-Reader zelf staat nog wel data, en ook het wegschrijven naar InfluxDB blijft werken.

Zodra ik de MQTT broker/connection disable en dan weer enable werkt het weer.

Ik heb zelf even gekeken naar wat er op de queue gezet wordt en het lijkt er op dat hij ALLEEn de ID opstuurt. Dus zeg maar alleen de eerste regel van het bericht

dsmr/reading/id 25459933
dsmr/reading/id 25550983
dsmr/reading/id 25561729
dsmr/reading/id 25479906
dsmr/reading/id 25501059
dsmr/reading/id 25510984

Na herstarten zitten alle tussenliggende regels er wel weer tussen

dsmr/reading/id 26348050
dsmr/reading/phase_voltage_l3 236.0
dsmr/reading/phase_currently_delivered_l3 0.324
dsmr/reading/phase_currently_delivered_l2 0.456
dsmr/reading/phase_currently_delivered_l1 0.046
dsmr/reading/electricity_currently_delivered 0.827
dsmr/reading/timestamp 2022-01-16T15:00:06Z
dsmr/reading/id 26348051
dsmr/reading/phase_voltage_l3 235.0
dsmr/reading/phase_currently_delivered_l3 0.301
dsmr/reading/phase_currently_delivered_l2 0.470
dsmr/reading/phase_currently_delivered_l1 0.047
dsmr/reading/electricity_currently_delivered 0.820
dsmr/reading/electricity_delivered_1 11327.338
dsmr/reading/timestamp 2022-01-16T15:00:07Z

(newlines vallen weg in de berichtvoorbeelden)

DSMR-reader version

4.19

DSMR-reader platform

Docker (e.g. Xirixiz)

Debug info dump

No response

[dennissiemensma]

Bedankt voor je melding. Je kunt het beste DEBUG-logging inschakelen als dit vaker gebeurt. Je zou dan exact moeten zien wat DSMR-reader doet, queue'd en verstuurt.

• https://dsmr-reader.readthedocs.io/nl/latest/how-to/troubleshooting/enabling-debug-logging.html

Waren er op dat moment geen andere fouten of waarschuwingen in DSMR-reader?

[Janoz-NL]

Ik heb debugging aangezet. Over een week weet ik hopelijk meer

[Janoz-NL]

Zo te zien lijkt het nu weer te gebeuren. Na verloop van tijd komen er steeds minder meetresultaten binnen. Ik zie nu alleen id's voorbij komen op het mqtt kanaal. Het lijkt er op dat hij alles afkeurt omdat het 'hetzelfde is als het vorige bericht'. Mogelijk zit daar iets niet goed.

log.txt

Dit is het log. en hoewel daar staat dat sommige berichten wel doorkomen zie ik alleen maar ID's op het kanaal en heel af en toe phase_voltage_l3 en extra_device_timestamp en phase_currently_delivered_l1

[dennissiemensma]

Bedankt voor je update. Dit verklaart een hoop.

Wat er gebeurt is dat DSMR-reader alle MQTT-berichten met een retain vlag stuurt. Dat betekent dat de broker altijd de laatste waarde per topic bewaart, ook als er pas later nieuwe clients (of dezelfde) verbindt. Daarom checkt DSMR-reader per topic of er uberhaupt een andere waarde gestuurd gaat worden. Dit scheelt een hoop verkeer, vooral voor topics die amper veranderen.
Echter kan het zijn dat dat niet lekker werkt als de client daar niet mee om kan gaan.

Edit: Hiervoor is al een envvar: DSMRREADER_MQTT_MAX_CACHE_TIMEOUT=0
https://dsmr-reader.readthedocs.io/nl/v4/reference/env-settings.html#dsmrreader-mqtt-max-cache-timeout

[dennissiemensma]

BIj nader inzien, zie https://dsmr-reader.readthedocs.io/nl/v4/reference/env-settings.html#dsmrreader-mqtt-max-cache-timeout

[dennissiemensma]

Laat maar weten als dit het desondanks niet oplost.

[Janoz-NL]

IK heb het aangepast. Ik ga kijken. Wel vreemd dat hij er dan na een dag of 7 mee ophoud. Zou het kunnen dat hij niet alleen de laatste waarde onthoud? Op een gegeven moment zijn veel mogelijke variaties van het verbruik wel doorgestuurd.

Sowieso vind ik caching ietwat vreemd. Het zijn meetwaarden. Als op moment X mijn waarde A is dan is dat zo. Als mijn waarde heel stabiel is dan wil ik wel voor elk moment die stabiele waarde weten. Stel op X+1 is het ook A, maar op X+2 is het B, dan wil ik in mijn rapportage niet terug zien dat op moment X mijn waarde (A+B)/2 is, maar dat de wijziging alleen optrad tussen moment X+1 en X+2

[dennissiemensma]

Bedankt voor je aanvulling. Het kan zijn dat dat er een mogelijke bug in zit, want de cachingduur is standaard max 1 uur bedenk ik me nu, dus ik zal hier ook even MQTT aanzetten.

Sowieso vind ik caching ietwat vreemd. Het zijn meetwaarden. Als op moment X mijn waarde A is dan is dat zo.

Caching werkt doorgaans prima, maar in bepaalde situaties kan het bijten. Helemaal als dus client dus een update op elk topic verwacht, ook als die niet veranderd is.
Voor sommige topics is het namelijk prima dat er pas een update komt als die veranderd is, maar voor andere wellicht niet. Ik kan er echter geen onderscheid in maken. De gedachte achter split-topics waren de directe mapping op dashboards/tellers, waarbij het dus niet uit maakt of er wel of geen update komt als de waarde onveranderd is.

Ik kan me verder wel vinden in je punt hoor. Ik denk dat dit vooral bij split-topics een issue kan zijn, want bij de JSON updates die DSMR-reader stuurt krijgt de client gewoon een volledige update omdat door het ID of tijdstip erin het per definitie "veranderd" is. Dat is wat je eigenlijk zoekt als je wilt dat alle waardes tegelijkertijd bijgewerkt moeten zijn.
DSMR-reader biedt MQTT aan met daarin diverse formaten voor topics en voor de rest hebben anderen er tegenaan gebouwd. Echter is hier nooit "hard" iets over vastgelegd. Ik denk dat het daarom voor nu een beetje behelpen is.

Ik zal kijken of ik het kan omdraaien. Standaard caching en duplicate-checks uit en op verzoek aan te zetten als de performance er onder lijdt. De een zal namelijk slechts 5 topics aan hebben en een andere gebruiker kan er zo 30 hebben.
Want dit is om DSMR-reader te ontlasten, zodat er geen vertraging optreedt in het opstellen en versturen van alle updates elke seconde. Want er gebeurt uiteraard veel meer binnen die seconde, behalve MQTT-afhandeling.

[dennissiemensma]

Ik zal het via #1561 wijzigen

[Janoz-NL]

Het probleem is inderdaad nog niet opgelost. Ik zie nu alleen ID's en extra_device_timestamps voorbij komen. Ik gebruik de MQTT koppeling van dsmr alleen om mijn gegevens naar Home Assistant te sturen. Met de influxDB heb ik verder geen enkel probleem. MQTT gebruik ik verder ook voor een aantal andere zaken en die hebben ook geen problemen

[Janoz-NL]

Als ik naar de logging kijk lijkt het er op dat hij niet veel doet met caching op 0. Nog steeds lijkt het dat er dingen rejected worden. Ik heb alleen niet zo'n zin om mijn logging publiekelijk op het internet te gooien. Is ere een andere manier/kanaal om hier even samen naar te kijken?

[dennissiemensma]

Als ik zelf sub op het topic krijg ik alleen de ID's binnen en geen data

Bekijk je een specifiek topic of een wildcard?

---

Wat ik vreemd vind is dat ik meerdere MQTT logging heb lopen en met geen enkel ander heb ik problemen. Ik gebruik zelf de paho_mqtt client en doe een simpele connect en vervolgens publish. Dat draait nu al meerdere maanden stabiel.

Ik denk eerlijk gezegd dat het issue niet zozeer in de manier van versturen zit, maar in de logica er omheen. Vandaar ook dat ik de logs nodig heb, want ik vermoed dat er iets anders speelt.

---

Nog steeds lijkt het dat er dingen rejected worden.

Als het goed is zie je deze melding niet meer: https://github.com/dsmrreader/dsmr-reader/blob/v4/dsmr_mqtt/services/messages.py#L37
Maar mogelijk deze wel: https://github.com/dsmrreader/dsmr-reader/blob/v4/dsmr_mqtt/services/messages.py#L44

Als dat zo is dan wordt de queue mogelijk niet snel genoeg verwerkt. Zou je anders ook nog een dsmr-debug-info willen delen? Zie "About" pagina in je installatie. Daar staan geen "gevoelige" gegevens in, maar wel instellingen en data hoeveelheden.

---

Is ere een andere manier/kanaal om hier even samen naar te kijken?

Je mag het eventueel mailen naar github at dennissiemensma punt nl.

[dennissiemensma]

Overigens verwacht ik dat over een week DSMR-reader v5 beschikbaar is. Daar is ook de check weggehaald op dubbele berichten en zou die altijd moeten versturen.

Dat zeggende hebben zou ik graag wel de oorzaak bij je achterhalen. Het kan namelijk een breed probleem zijn.

[Janoz-NL]

Ik bekijk een wildcard en mijn vermoeden is ook dat er iets niet snel genoeg verwerkt wordt. Mijn slimme meter is een v5 en stuurt elke seconden een statusupdate. Als ik kijk naar de log lijkt het alsof hij nog niet klaar is met het versturen van alle berichten voordat de volgende data alweer binnenkomt. Ik vond het wat vreemd, want het kan geen resource probleem zijn. dsmr-reader draait op een fatsoenlijke i5 welke voornamelijk aan het duimendraaien is. Ik denk dus dat het mogelijk komt doordat de backend aangeeft telkens een seconde te gaan slapen. Ik zal een stuk log mailen

[dennissiemensma]

Je kunt in dat geval de backend-sleep op 0 of 0.1 zetten. Of je moet de datalogger sleep wat hoger zetten als je de interval van telegrammen niet perse elke seconde nodig hebt. Als je dus inderdaad fatsoenlijke hardware hebt zou ik het eerste proberen (backend sleep verlagen)

[Janoz-NL]

Ik zie in mijn MQTT log wel de volgende meldingen constant voorbij komen:

1645107446: Warning: Received PUBREL from DSMR-reader for an unknown packet identifier 29744.
1645107448: Warning: Received PUBREL from DSMR-reader for an unknown packet identifier 29766.
1645107448: Warning: Received PUBREL from DSMR-reader for an unknown packet identifier 29777.
1645107449: Warning: Received PUBREL from DSMR-reader for an unknown packet identifier 29799.

[Janoz-NL]

Sterker nog, ik heb ze denk ik bij elkaar kunnen vinden:

DSMR-reader:

2022-02-17 15:23:25,181 DEBUG    broker       run                             106 | MQTT: Deleting published message (#97009097) from queue
2022-02-17 15:23:25,182 DEBUG    broker       run                              79 | MQTT: Publishing queued message (#97009096) for dsmr/reading/phase_currently_returned_l2: 0.000
2022-02-17 15:23:25,182 DEBUG    broker       on_log                          159 | MQTT: (Paho on_log) Sending PUBLISH (d0, q2, r1, m38381), 'b'dsmr/reading/phase_currently_returned_l2'', ... (5 bytes)
2022-02-17 15:23:25,183 DEBUG    broker       run                              98 | MQTT: Waiting for message (#97009096) to be marked published by broker
2022-02-17 15:23:25,183 DEBUG    broker       on_log                          159 | MQTT: (Paho on_log) Received PUBREC (Mid: 38381)
2022-02-17 15:23:25,183 DEBUG    broker       on_log                          159 | MQTT: (Paho on_log) Sending PUBREL (Mid: 38381)
2022-02-17 15:23:25,183 DEBUG    broker       run                              98 | MQTT: Waiting for message (#97009096) to be marked published by broker
2022-02-17 15:23:25,183 DEBUG    broker       on_log                          159 | MQTT: (Paho on_log) Received PUBCOMP (Mid: 38381)
2022-02-17 15:23:25,183 DEBUG    broker       run                             106 | MQTT: Deleting published message (#97009096) from queue

mosquitto:
1645107930: Warning: Received PUBREL from DSMR-reader for an unknown packet identifier 38381.

[dennissiemensma]

Bedankt voor je melding. Het zegt mij niets, behalve de termen zelf, en lijkt soms voor te komen met mogelijk een issue bij de client, alleen verstuurt de Paho MQTT client deze voor DSMR-reader, dus ik ben benieuwd of ik daar nog wat aan kan veranderen.
De PUBREL is onderdeel van het MQTT protocol bij QoS 2, wat DSMR-reader gebruikt via Paho: http://www.steves-internet-guide.com/wp-content/uploads/mqtt-publish-flow-qos-2.jpg

Je zou kunnen kijken of je specifiek een ID uit de waarschuwing kan vinden in de log van DSMR-reader, om te zien of die bijvoorbeeld te snel verstuurd wordt. In je fout zie ik bijvoorbeeld packet identifier 29744 en in je log Mid 38381. Dus wellicht als je ze naast elkaar legt dat je wel snel een match vindt, gezien ze niet heel ver uit elkaar liggen.

Zo ja dan mag je wel de log delen gerelateerd aan dat ID (welk ID je ook kiest op te zoeken).

[dennissiemensma]

Ik zie nu pas je onderste regel. Zijn dat alle logs voor dat ID? Want als ik bovenstaand schema erbij pak, zie ik niet zo 1-2-3 een issue in de volgorde van ontvangen/versturen.

Ook omdat Paho een PUBCOMP lijkt te ontvangen van je broker, waarbij dat een antwoord op de PUBREL is.