Foutafhandeling MinderGas-export / e-mailverzending timeout

[dopeh]

Hi!
Sinds 24-02 16:44 lijken de readings niet meer goed verwerkt te worden. Er stonden inmiddels best wat "Process behind schedule" meldingen, en het aantal unprocessed readings neemt langzaam aan toe.
In de logs eigenlijk geen extra informatie, ook niet met DEBUG level.
Via supervisord al de services herstart, dat lijkt geen effect te hebben.
Wat wel effect heeft is de pi rebooten, dan worden er een stuk of 1000 readings weer geprocessed, maar na een paar minuten begint het weer op te lopen en lijkt hij er mee gestopt. Hij stond op 20.000 readins, na 4x rebooten ben ik terug tot zo'n 16.000, maar hij pakt hem niet meer automatisch op.

Helaas geen idee waar ik verder moet zoeken voor de oorzaak dus tips zijn zeer welkom!
Thanks.

DSMR-READER
    App / Python / Database                                                        v4.6 / v3.7.3 / postgresql
    Backend sleep / Datalogger sleep / Retention cleanup                                  1.0s / 10.0s / 168h
    Telegram latest version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                             168004
    Consumption records electricity / gas (est.)                                                18064 / 13203

UNRESOLVED ISSUES
    Process behind schedule: Generate day and hour statistics                                  22 minutes ago
    Too many unprocessed readings: 16227                                                   1 day, 3 hours ago
    Process behind schedule: Backup per email                                             1 day, 15 hours ago

/var/log/supervisor/dsmr_backend.log

Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
[2021-02-26 07:13:17,031] ERROR    No recent gas reading found
Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 69, in export
    ).order_by('-read_at')[0]
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/query.py", line 325, in __getitem__
    return qs._result_cache[0]
IndexError: list index out of range

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 32, in run
    export()
  File "/home/dsmr/dsmr-reader/dsmr_mindergas/services.py", line 71, in export
    raise AssertionError(_('No recent gas reading found'))
AssertionError: No recent gas reading found
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging

/var/log/supervisor/dsmr_datalogger.log

Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
root@raspberrypi:~# 

[dennissiemensma]

Bedankt voor je melding. Ik denk dat je tegen een soort deadlock aanloopt als ik het zo 1-2-3 zie. Ik zal dat verbeteren in een volgende release.
Het crasht vermoedelijk doordat er geen gasmeting gevonden kan worden voor de MinderGas-export, omdat de verwerking van de metingen achterloopt. En de metingen kunnen niet verwerkt worden omdat die mogelijk eerst de MinderGas-export probeert en faalt.

Voor nu ben je mogelijk geholpen door je MinderGas-export in DSMR-reader even uit te zetten. Je kunt kijken of het verwerken van de gegevens daardoor beter gaat.

[dopeh]

Dank voor je reactie. Ik heb de MinderGas export uitgezet, dan gaat die melding inderdaad weg, maar helaas liep de verwerking daarmee nog niet door.
De reboot was niet meer nodig, met een supervisorctl restart dsmr_backend ging hij weer even verder, waarbij hij ongeveer (of misschien wel precies) 1000 readings verwerkte en daarna weer stopte. Dan zag ik het aantal readings weer oplopen. Inmiddels heb ik de achterstand op die manier weggewerkt, alleen lijkt het er nog niet op dat binnenkomende readings nu wel worden verwerkt (kijkend naar de live graphs).

De backup heb ik uitgezet waarmee die melding ook weg is. Er staan nu nog 3 meldingen open die hij niet verder oppakt.

DSMR-READER
    App / Python / Database                                                        v4.6 / v3.7.3 / postgresql
    Backend sleep / Datalogger sleep / Retention cleanup                                  1.0s / 10.0s / 168h
    Telegram latest version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                             115865
    Consumption records electricity / gas (est.)                                                20785 / 13203

UNRESOLVED ISSUES
    Process behind schedule: Generate consumption data                                         17 minutes ago
    Process behind schedule: Retention data rotation                                              2 hours ago
    Process behind schedule: Generate day and hour statistics                                    14 hours ago

De log files laten niks nieuws zien, behalve dat ik in de dsmr_backend.log niet terug zie als ik in .env de DEBUG aan zet.

root@raspberrypi:~# tail /var/log/supervisor/dsmr_backend.log
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/v4/troubleshooting.html#logging
^C
root@raspberrypi:~# 

Enig idee hoe ik kan zorgen dat hij weer zaken gaat verwerken aan de achterkant? Deze situatie lijkt heel spontaan te zijn ontstaan zonder dat ik een directe aanleiding kan bedenken.

[dennissiemensma]

• Wat voor Pi gebruik je?
• Draai je het op de Pi toevallig via Docker?
• Je kunt DSMRREADER_LOGLEVEL=DEBUG nogmaals tijdelijk aanzetten (vergeet niet ook om via supervisor te herstarten om het door te voeren) en dan nog een keer in de backend log kijken. Als het goed is zie je dan namelijk ook informatieve debug-statements die aangeven wat die precies doet en welke taak. En wellicht ook waarom die iets niet doet.

[dopeh]

• Raspberry Pi 3 Model B Rev 1.2
• Nee. Wel Postgres db in Azure (cloud). Draait stabiel sinds april 2020.
• Interesting, dat had ik eerder gedaan en dan de post_deploy.sh gedraait. Dit keer geen post_deploy.sh maar restart via supervisorctl en nu zie ik wel de debug messages. Ik zag eerder alleen de debug messages van de datalogger in de logs komen na de post_deploy.sh, niet van de backend.

[2021-02-26 22:12:07,066] DEBUG    dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
[2021-02-26 22:12:08,089] DEBUG    SP: 1 backend service(s) ready to run
[2021-02-26 22:12:08,090] DEBUG    SP: Running "Generate consumption data" (dsmr_consumption.services.run)
[2021-02-26 22:12:08,705] DEBUG    Compact: Processed reading: 12890246 @ 2021-02-26 22:11:10+01:00
[2021-02-26 22:12:08,931] DEBUG    Compact: Processed reading: 12890247 @ 2021-02-26 22:11:21+01:00
[2021-02-26 22:12:09,048] DEBUG    Compact: Processed reading: 12890248 @ 2021-02-26 22:11:32+01:00
[2021-02-26 22:12:09,206] DEBUG    Compact: Processed reading: 12890249 @ 2021-02-26 22:11:43+01:00
[2021-02-26 22:12:09,331] DEBUG    Compact: Processed reading: 12890250 @ 2021-02-26 22:11:54+01:00
[2021-02-26 22:12:09,370] DEBUG    Compact: Waiting for newer readings before grouping data...
[2021-02-26 22:12:09,394] DEBUG    SP: Rescheduled "Generate consumption data" to 2021-02-26 22:12:24.371473+01:00 (ETA 0:00:14.976907)
[2021-02-26 22:12:09,535] DEBUG    dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
[2021-02-26 22:12:09,724] INFO     dsmr_backend.management.commands.dsmr_backend: Detected signal #15
[2021-02-26 22:12:09,725] INFO     dsmr_backend.management.commands.dsmr_backend: Exiting on next run...
[2021-02-26 22:12:10,536] DEBUG    CLIENTS: Terminating 0 client(s)
[2021-02-26 22:12:10,537] DEBUG    dsmr_backend.management.commands.dsmr_backend: Exited

Het lijkt nu alsof hij de draait weer heeft opgepakt want hij heeft de overige meldingen weggewerkt en in de debug zie ik dat hij de binnenkomende readings verwerkt.

[dennissiemensma]

Mooi! In dat geval kun je nog eens proberen om de MinderGas-export weer aan te zetten. En als alles goed draait, vergeet de DEBUG-log niet terug te zetten op ERROR + restart.

[dopeh]

Hi,
De situatie lag toch anders dan gedacht. De readings waren opnieuw vastgelopen en werden niet meer geimporteerd. Nogmaals de debug flag aangezet, en het blijkt dat hij bleef hangen op het versturen van de email met incremental back-up. De uitgaande SMTP klopte niet meer (hij probeerde TLS connectie te maken terwijl het SSL moest zijn), en er lijkt geen time-out te zitten op het connecten naar de server:

[2021-02-28 18:29:33,772] DEBUG    SP: Rescheduled "Generate consumption data" to 2021-02-28 18:29:34.750979+01:00 (ETA 0:00:00.978167)
[2021-02-28 18:29:33,774] DEBUG    SP: Running "Backup per email" (dsmr_backup.services.email.run)
[2021-02-28 18:29:33,856] INFO      - Creating new partial backup: /tmp/tmpzi0aw5d7/dsmrreader-postgresql-partial-backup-2021-02-28.sql
[2021-02-28 18:29:38,571] DEBUG     - Backup exit code: 0
[2021-02-28 18:29:38,644] INFO      - Created and compressed statistics backup: /tmp/tmpzi0aw5d7/dsmrreader-postgresql-partial-backup-2021-02-28.sql.gz
[2021-02-28 18:29:38,833] DEBUG    Email: Preparing to send email using mail server mail.XXX.com:465
[2021-02-28 18:29:38,839] DEBUG    Email backup: Sending an email to XXX@XXX (DSMR-reader day/hour statistics backup)

En daar bleef het back-end proces hangen. Als ik vervolgens de dsmr_back-end herstartte (zoals ik eerder deed) ging hij opnieuw een heleboel readings processen tot hij weer de incremental back-up probeerde te versturen en daar bleef hij opnieuw hangen. De MinderGas gaat ook niet goed, maar die throwt netjes een exception waardoor het proces wel doorloopt. Er zit alleen geen lekkere afhandeling op het verifieren van de mail server.

Andere "issue" is dat in de documentatie staat dat je na het wijzigen van de debug flag "post_deploy.sh" kan draaien, deze doet echter een supervisorctl reload dsmr_backend (geen restart) en dan lijkt de debug instelling niet geladen te worden bij het dsmr_backend proces (wel bij het dsmr_datalogger proces). Bij een daadwerkelijke supervisorctl restart dsmr_backend wordt wel netjes de debug aangezet.

Dus, probleem opgelost door SMTP instelling te goed te zetten en de debug flag op de juiste manier te laden :-)

[dennissiemensma]

Bedankt voor je aanvullingen! Ik zal beide foutsituaties verbeteren.

Ik denk dat je net pech hebt gehad dat het proces bleef hangen, want het deploy-script doet niets met supervisor maar stuurt een kill -HUP naar alle processen. Die zetten dan intern een bepaalde vlag en stoppen zichzelf na afronding van hun huidige taak (waardoor Supervisor ze weer start). Echter kwam in jouw geval het proces nooit toe aan de afronding van de huidige taak.
Hoe dan ook zal ik de docs bijwerken naar de supervisor herstart, gezien die ook wat betrouwbaarder is als de processen bijvoorbeeld uberhaupt niet draaien.

[dopeh]

Ah, helder. Thanks!

[dennissiemensma]

Voor de volgende release docs aangepast. Verder e-mail timeout toegevoegd en foutlogging voor Buienradar wat versimpeld.

[dennissiemensma]

Zojuist uitgebracht in v4.13.