Dsmr-reader: Dataverwerking stopt bij afwezigheid (mysql)dump tool

[pyrocumulus]

Sinds de upgrade naar 1.6 stopt elke nacht rond 3 uur de dataverwerking. Met als gevolg dat zodra ik 's ochtends op sta er ruim 12.000 telegrammen open staan om te verwerken. Meestal heb ik 's ochtends niet echt tijd om er diep in te duiken dus wat ik nu doe is gewoon m'n pi maar herstarten. Maar dat is uiteraard niet zo fijn maar gelukkig is het de verwerking die er uit vliegt en niet de logger zelf.

Vóór 1.6 heb ik het in ruim een maand slechts twee keer meegemaakt. Ik heb een DSMR v5 slimme meter, dus ook toen kwamen er al veel meer telegrammen binnen dan DSMR reader oorspronkelijk verwachtte; maar dat was nooit echt een probleem.

• Gebeurt er iets specifieks rond die tijd wat wellicht de aanleiding kan zijn voor het stoppen?
• Wat zou ik kunnen doen om dit probleem verder te achterhalen? Weet niet of het me 's ochtends lukt om wat te testen maar ik weet nu eigenlijk ook niet wat ik zou moeten doen als ik wel tijd.
• Is het misschien een idee om een soort health checking in DSMR reader te bouwen? Als het aantal openstaande telegrammen boven een bepaalde grenswaarde komt, bijvoorbeeld 300 (5 minuten met 1 telegram/seconde) dat dan gekeken wordt of het backend proces nog wel leeft? En dan het proces herstarten als nodig.

[dennissiemensma]

Bedankt voor het melden van dit probleem. Ik zou niet zo 1-2-3 een oorzaak weten, behalve dat het maken van een backup de verwerking (tijdelijk) stopt, gedurende een paar minuten.
Sinds de nieuwe release heb ik hier wat hulp toegevoegd voor debuggen.

In dit specifieke geval zou je kunnen kijken in de logfile van de backend. Deze staat in /var/log/supervisor/dsmr_backend.log en je kunt, op een moment dat jou uitkomt, daarin terugkijken naar de tijd dat het misgaat.

Qua health checking komt er iets voor in de applicatie, mogelijk zelfs via notificaties. Ik ben al even kort bezig geweest met #208, maar daar zit nog wel wat werk in voor mij.

[pyrocumulus]

Fijn dat je logging toegevoegd hebt op dat gebied, ik dacht dat ik op de vroege ochtend met een tail op de supervisor bezig zou moeten :) Ik ga morgenochtend het log eens bekijken. Thanks voor de info! Ik zal hier terugkoppelen wat er uit komt.

208 zit zo te zien in dezelfde hoek maar dan juist de logging plaats van de verwerking. Maar dat klinkt inderdaad goed!

[pyrocumulus]

Ik ging even de configuratie van de backups bekijken en toen kreeg ik al een beetje het idee dat het daar wel aan kon liggen:

Geen recente backup.

Je hebt goed gegokt, het is inderdaad een probleem bij het maken van de backup. Ik heb het laatste deel van de log hier neergezet: https://gist.github.com/pyrocumulus/de1755c4796b44853d4811d81c07820c

Dit is wat er mis gaat:
```

• Creating new backup.

Uncaught exception :: [Errno 2] No such file or directory: 'mysqldump'
> :: File "/home/dsmr/dsmr-reader/dsmr_backend/management/commands/dsmr_backend.py", line 29, in run
raise current_response
```

En dat komt ongetwijfeld door mijn specifieke setup. Ik draai gebruik wel mysql als datastore maar die draait voor performance/backup redenen niet op de pi zelf maar op een nas. Was bij het installeren van dsmr-reader nog wel even wat geknoei maar is me wel gelukt. Betekent wel dat ik de bijbehorende dependencies/packages niet geïnstalleerd heb en daar ga jij in dsmr_backend.py op basis van de vendor wel vanuit. Mijn eigen schuld :) Nu maakt mijn nas zelf al backups van de MariaDB dus ik ga de backup functionaliteit van dsmr-reader simpelweg uitschakelen. Ik denk dat het dan opgelost is voor mij.

Wel is het misschien fijn om de backend tegen dit soort errors te beveiligen zodat niet de hele dataverwerking onderuit gaat in zo'n situatie. Voor ik het vergeet: zijn er meer plaatsen waar je van de aanwezigheid van deze tooling uit gaat, waar ik wellicht rekening mee moet houden?

[dennissiemensma]

Erg bedankt voor het uitzoeken! Ik heb daar inderdaad geen rekening mee gehouden, maar het lijkt me goed dat ik er in de toekomst een check of iets voor maakt.

Wat betreft andere tooling, volgens mij is dit het enige. Mocht je toch nog ergens tegenaan lopen dan hoor ik het graag. Ik laat dit ticket staan om er later een check voor te maken.

[pyrocumulus]

Ben al even bezig maar helaas stopt de verwerking bij mij nog steeds om 3 uur 's nachts en ik begrijp er eigenlijk niet zo heel veel meer van. Als ik de log of de tail bekijk, kom ik altijd op foutmeldingen als de volgende uit: https://gist.github.com/pyrocumulus/89750ae2dfe0ae9550200f055dc3f1f6

De enige variatie is de class waar get_solo() op uitgevoerd wordt. Ik vond dit topic over Django en deze melding en heb de dingen daaruit geprobeerd toe te passen. Waaronder de timeouts van MariaDB verhoogd naar 24 uur en zelfs de CONN_MAX_AGE naar 0 gezet van de 60 die jij uitlevert; daarna een volledige reboot gedaan (geen .\reload.sh trouwens maar dat is niet zo erg toch?). Maar dan nog kan ik niet begrijpen waarom het specifiek 3 uur 's nachts steeds fout gaat. Mijn NAS draait dan een lokale backup van MariaDB maar er draait ook een cloud backup om 2 uur en dat is blijkbaar geen probleem.

Heb jij misschien nog ideeën of moet ik dit in een apart issue melden? Ik zit er nu aan te denken om een standaard reboot om 3:05 uit te voeren middels een script. De backend komt namelijk niet meer uit deze fout situatie zodra het eenmaal begint.

[dennissiemensma]

De melding MySQL server has gone away komt voor wanneer de databaseverbinding (onverwacht) verbroken wordt. Meestal door een actie van de database aan de serverzijde. Het kan zijn dat je NAS de DB-verbinding verbreekt voor backup, maar dat blijft gissen. Je zou dit kunnen uitsluiten door bijvoorbeeld eenmalig handmatig een backup te starten en te kijken of het daardoor komt.

Ik zou desondanks verwachten dat het ORM (Django) dit soort dingen zelf afhandelt en opnieuw verbindt, maar blijkbaar gebeurt dat in deze situatie niet.
Ik heb hier daarom niet direct een oplossing voor, maar ik wil dit zeker een keer proberen te reproduceren hier. Wellicht dat een workaround in de code tzt werkt.

Zou je eens kunnen kijken of puur het herstarten van het backendproces dit ook 'verhelpt'? Dat kan via: sudo supervisorctl restart dsmr_backend. Ik zou verwachten dat dat ook de verbinding opnieuw opbouwt, zonder reboot.

[pyrocumulus]

Ik heb nog even verder zitten kijken en ik denk inderdaad dat mijn eigen backup de oorzaak is. De cloud backup die rond 2 uur draait, had die nacht niet gedraaid door een andere oorzaak. En draait nu juist later dan die van 3 uur, wanneer het kwaad al geschied is. Dus de timing van het probleem komt exact overeen met mijn backupschema. En daarbij lees ik dat Synology's backup functionaliteit inderdaad MariaDB tijdelijk neerhaalt. Oeps.

Je zou verwachten dat Django dit zou moeten kunnen overleven of in elk geval opnieuw zou moeten verbinden als dit optreedt maar dat gebeurt helaas niet. Beetje jammer! Nu is MySQL ondersteuning deprecated dus ik verwacht niet heel veel van eventuele fixes van jouw kant. Ik moet me er maar even mee redden :)

Ik heb de configuratie van supervisor aangepast zodat deze via http bereikbaar is. Dan hoef ik geen ssh sessie op te starten om de subprocessen te beheren en kan ik dat 's ochtends wel even testen :) Kostte nog wel even wat tijd om te configureren vanwege permissies maar was het waard. Ik ga het herstarten van het backend proces testen in de fout-situatie. Mocht dat ook afdoende zijn dan script ik dat desnoods wel in een cronjob na de backup. Dat laat ik dan morgen nog wel weten.

[dennissiemensma]

Top fijn dat je er zo snel zelf uit bent gekomen! Ik ga hier zeker nog wel een keer naar kijken (ik ben overtuigd dat Django een verbindingsfout zelf moet kunnen afvangen, wellicht doe ik toch iets raars), alleen met wat lagere prio, gezien er nu een soort 'workaround' is.. tot die tijd. :]

[pyrocumulus]

Het herstarten van het backend proces is inderdaad voldoende om het op te lossen. Die hangende databaseconnectie zit dus ergens in het proces. Wat ik wel gek vindt overigens - en misschien helpt jou dat wat met een eventuele fix - is dat het dsmr_datalogger proces dit wel overleeft. Of gebruikt deze geen Django intern?

Anyways, ik ga kijken of ik het herstarten kan schedulen zodat ik er in elk geval in normale scenario's geen last van heb. Zit ik alleen nog even met de restarts van de nas bij bijvoorbeeld updates. Maar dat is niet zo heel vaak :]

Ben je trouwens geïnteresseerd in de doorlopen stappen om die supervisor via http beschikbaar te maken en/of de andere permissies voor het 'besturen' van supervisor? De permissies aanpassen is misschien sowieso wel fijn zodat iedereen minder hoeft te sudo-en :) Ik wil het wel uittypen in een stukje voor in de docs.

[dennissiemensma]

Fijn dat het herstarten voldoende is, al is het maar een workaround. Het is inderdaad vreemd dat alleen de backend crasht en niet de datalogger.

Wat betreft permissies en Supervisor: Het instellen van de webinterface en permissies is zeker mooi, maar ik ben wel bang dat het wat complexiteit toevoegt. Dus voor nu denk ik dat het wellicht begrijpbaarder is om dat voor nu even uit de docs te laten (ik waardeer het overigens zeker hoor!)

Daarnaast zou je nog kunnen kijken of het sturen van een hangup kill signaal naar het Supervisor proces ook afdoende is. Daar is ook geen sudo voor nodig, al heb je het nu lokaal ook al helemaal werkend. Het uitrolscript roept namelijk onderwater reload.sh aan en die stuurt een kill -HUP naar Supervisor. Die doet dan vervolgens weer een 'graceful' herstart (al weet ik niet of dat ook werkt als het proces zelf al gecrasht is).
Dus dit zou ook nog kunnen werken, zonder sudo: cat /var/tmp/dsmrreader--dsmr_backend.pid | xargs kill -HUP.

Wellicht dat ik in de toekomst nog even ga kijken naar de oorzaak van de crash.

[pyrocumulus]

Prima, ik dacht ook al dat het wellicht wat te geavanceerd zou zijn maar wilde het wel aanbieden :)

De HUP zou ik inderdaad ook nog even kunnen testen. Maar voor de duidelijkheid, het dsmr_backend proces hangt niet écht. Als ik een tail op het proces doe zie ik gewoon elke 5 seconden activiteit maar het is gewoon telkens een exceptie vanuit één van de get_solo() methoden (varieert ook telkens) richting Django. Probleem zit uitsluitend in de kapotte database connectie die telkens opnieuw geprobeerd wordt. De scheduler lijkt dus gewoon te draaien. Ik denk dus dat die reload ook wel gaat werken omdat het proces wel gewoon reageert.

Dan laat ik het hier verder bij, tenzij ik nog iets bijzonders ontdek. Bedankt voor de assistentie en een fijn product ;)

[pyrocumulus]

Nog beetje feedback, gewoon omdat het kan.

• Ik zei dat de datalogger bleef werken hé? Dat is toch niet helemaal waar. De datalogger gaat wel degelijk onderuit op het backup moment maar op zo'n manier dat het hele proces knalt. Dit proces wordt daarna door de supervisor weer opnieuw gestart. Ik zie namelijk elke ochtend dat het datalogger process grofweg een runtime heeft van (NOW() - 3:00).
• Het herstarten van de backend via crontab werkt prima; is nog iets fijner dan de -HUP die de hele Supervisor een schop geeft (als ik het goed begrijp).

[dennissiemensma]

Oke bedankt voor de feedback en goed om te weten. Binnenkort komt een nieuwere versie van Django uit, wellicht dat die wat oplost (ik vermoed dat het iets anders is).

Wat betreft Supervisor, het werkt indirect hetzelfde, maar gebruik vooral wat je fijn vindt. Een -SIGHUP gaat alleen naar het subproces van Supervisor (zoals datalogger of backend). Die vangt vervolgens het signaal af en zet daarna een vlaggetje om de 'eeuwige loop' van het command bij de volgende run af te breken.
Volgens mij doet Supervisor(ctl) hetzelfde, maar stuurt een SIGTERM (en wordt dus ook door bovenstaande code afgevonden. Dus nogmaals, gebruik vooral wat voor jou het beste werkt of makkelijkste in te stellen is. Uiteindelijk zou die weer moeten werken na de herstart.

[dennissiemensma]

@pyrocumulus heb je hier nog steeds last van met een recentere versie? In oktober is de applicatie ge-upgrade naar Django 1.11. Ik verwacht niet dat dat magisch dit issue oplost, maar wie weet...

[pyrocumulus]

Hey @dennissiemensma ! Ik ga voor je kijken. Ik heb het idee dat het probleem niet meer speelt. Mijn crontab voor na de backup draait nog wel maar ik reboot m'n nas wel regelmatig en kan me de laatste keer dat uitsluitend de backend verwerking gestopt was niet echt herinneren. Ik ga de crontab uitschakelen en ik kom hier z.s.m. op terug.

[pyrocumulus]

Het is blijkbaar nog wel steeds een probleem, in elk geval bij de nachtelijke backup. Vanochtend was de dataverwerking toch weer gestopt rond 3 uur en moest ik middels de supervisor de boel een schop geven. Blijkbaar gaan nu korte perioden van onbereikbaarheid voor de sql server wel goed, maar de nachtelijke backup is blijkbaar toch te lang. Ik heb geen nieuwe log trouwens van de error uit de backend. Als je daar interesse in hebt moet ik dat nog even voor elkaar zien te krijgen, maar 's ochtends doordeweeks komt dat niet zo lekker uit ;-)

Daarnaast kwam ik er achter dat de Status pagina niet meer bekijken is, als er een achterstand is. Dit was voorheen geen probleem. Zodra ik de Status pagina wilde bekijken om het aantal telegrammen achterstand te bekijken, bleef de pagina gewoon hangen. Met uiteindelijk een 504 Gateway timeout o.i.d. Toen uiteindelijk de achterstand weggewerkt was (dat kon ik beetje gokken via Dashboard) kon ik de statuspagina wel weer openen. Maar dit is denk ik een nieuw/ander probleem dan waar dit issue om gaat.

[dennissiemensma]

Bedankt voor je feedback. Jammer dat het niet opgelost is (hoewel het niet onverwacht is).

Qua logfiles kun je meestal een hele tijd terugkijken. Standaard roteert die 4 of 5 keer en kun je rustig, op een moment dat jou uitkomt, kijken of je een foutmelding kan vinden. Het zijn deze files:

/var/log/supervisor/dsmr_backend.log
/var/log/supervisor/dsmr_backend.log.1
/var/log/supervisor/dsmr_backend.log.2
/var/log/supervisor/dsmr_backend.log.3
/var/log/supervisor/dsmr_backend.log.4
/var/log/supervisor/dsmr_backend.log.5

[pyrocumulus]

Uiteindelijk had ik zelfs log.2 nodig om de meldingen van vanochtend 3 uur naar voren te halen. Er komt toch aardig wat tekst in dat log ;-)

Goed, ik heb de log bekeken maar fouten lijken nog exact hetzelfde als voorheen, dus dit:
https://gist.github.com/pyrocumulus/89750ae2dfe0ae9550200f055dc3f1f6

De trigger varieert wel tussen dsmr_mindergas / dsmr_weather / notification en nog een aantal andere maar de rest lijkt telkens hetzelfde: 2006 MySQL server has gone away. Ik denk dus verder wat je ook verwacht had, geen verschil vooralsnog.

[dennissiemensma]

Hmm dat lijkt inderdaad nog dezelfde fout. Bedankt voor het opzoeken.

[dennissiemensma]

Ik heb een mogelijke fix in #427 straks. De databaseverbinding wordt dan na elke run geforceerd gestopt, zodat die opnieuw verbindt. Mogelijk lost dat het op.

[pyrocumulus]

Ik ben benieuwd. Zal mijn test wel herhalen als ik die fix binnen heb 👍

[dennissiemensma]

De betreffende release is zojuist uitgebracht.

[pyrocumulus]

Volgens mij heeft het geholpen; nu lag helaas de datalogger er uit omdat de slimme meter kabel niet goed opgestart was na een reboot, maar de backend leefde vanochtend nog steeds (er was alleen geen data om te verwerken).

Ik bekijk het morgenochtend nog een keer en dan weet ik het 100% zeker maar het lijkt wel opgelost te zijn.

[pyrocumulus]

Duurde iets langer voor ik kon reageren maar het probleem is opgelost. Mijn crontab draait niet meer maar ik heb nog steeds geen hangende backend gezien.

Weer een stukje stabiliteit erbij! 😃

[dennissiemensma]

Bedankt voor het uitproberen!