Dataverwerking loopt achter bij wisselen naar woning zonder gasmeter

swerveshot commented 4 years ago

Wat gebruik je?

DSMR-reader version: v2.13b1 (huidige versie, development branch)
Hardware: Odroid U3
DSMR protocol: v4

Reproduceren issue

Geen idee. Waarschijnlijk pas te reproduceren als we een root cause hebben.

Description

Follow-up van issue #764. Toevallig constateerde ik ook op mijn installatie hetzelfde issue. Dat wil zeggen de dataverwerking loopt achter. Echter het bijwerken van dsmr-reader naar een versie hoger dan v2.10.0 verhelpt het mankement in mijn geval niet.

Helaas kan ik niet precies vertellen welke versie ik draaide toen het probleem optrad. Wellicht is dit nog te achterhalen met de deployment logs.

Nu ZOU het kunnen zijn dat dit issue nog steeds optreed omdat ik verhuisd ben en gewoon mijn huidige install heb gekoppeld op de P1 poort op het nieuwe adres. Complicerende factor hierbij is ook nog eens dat ik op het nieuwe adres geen gasverbruik meer heb omdat ik hier stadsverwarming heb.

_Om exact te zijn: laatste meting in dsmr_consumption_gasconsumption is van 2019-04-25 21:40:00+02. En de eerste meting in dsmr_consumptionelectricityconsumption op het nieuwe adres is van 2019-09-18 23:32:00+02. In de tussenliggende periode heeft DSMR Reader uit gestaan.

Aanvullend, de data in de dsmr_consumption_electricityconsumption kolom is recent.

dsmrreader=# select read_at from dsmr_consumption_electricityconsumption order by read_at desc limit 10;
        read_at
------------------------
 2020-01-02 09:34:00+01
 2020-01-02 09:33:00+01
 2020-01-02 09:32:00+01
 2020-01-02 09:31:00+01
 2020-01-02 09:30:00+01
 2020-01-02 09:29:00+01
 2020-01-02 09:28:00+01
 2020-01-02 09:27:00+01
 2020-01-02 09:26:00+01
 2020-01-02 09:25:00+01
(10 rows)

Bij dsmr_stats_hourstatistics en dsmr_stats_daystatistics zie ik helaas geen recente data.

dsmrreader=# select hour_start from dsmr_stats_hourstatistics order by hour_start desc limit 10;
       hour_start
------------------------
 2019-10-09 00:00:00+02
 2019-10-08 23:00:00+02
 2019-10-08 22:00:00+02
 2019-10-08 21:00:00+02
 2019-10-08 20:00:00+02
 2019-10-08 19:00:00+02
 2019-10-08 18:00:00+02
 2019-10-08 17:00:00+02
 2019-10-08 16:00:00+02
 2019-10-08 15:00:00+02
(10 rows)

dsmrreader=# select day from dsmr_stats_daystatistics order by day desc limit 10;
    day
------------
 2019-10-08
 2019-10-07
 2019-10-06
 2019-10-05
 2019-10-04
 2019-10-03
 2019-10-02
 2019-10-01
 2019-09-30
 2019-09-29
(10 rows)

Er is wel een klein aantal readings dat niet verwerkt is, maar dat lijkt mij redelijk onschuldig.

dsmrreader=# select count(id) from dsmr_datalogger_dsmrreading where processed = false;
 count
-------
    10
(1 row)

Het enige wat me opvalt als ik de dsmr_backend.log bekijk is (los van wat dropbox en buienradar gerelateerde events) dat er heel veel keren deze log regels worden weggeschreven.

[2019-10-27 17:29:58,599] ERROR    2019-10-27 02:00:00
NoneType
[2019-10-27 17:29:58,600] ERROR    no element found: line 1, column 0
NoneType

Maar dit is alleen op 27 oktober en heeft steeds een 'echte' timestamp aan het begin van het event, maar steeds exact '2019-10-27 02:00:00' in de data. Na 27 oktober komt dit ook niet meer voor.

swerveshot commented 4 years ago

Okay, dit zou ook iets kunnen zijn. Ik zie in /var/log/supervisor/ de volgende file.

-rw------- 1 root root 263 Oct  9 12:57 /var/log/supervisor/dsmr_datalogger-stderr---supervisor-SFOiid.log

Met daarin een enkele regel:

[2019-10-09 12:57:42,264] ERROR     [!] Exception raised in run(): column dsmr_datalogger_dataloggersettings.track does not exist
LINE 1: SELECT "dsmr_datalogger_dataloggersettings"."id", "dsmr_data...
                                                          ^

Een query op de kolom dsmr_datalogger_dataloggersettings levert de volgende data op.

dsmrreader=# select * from dsmr_datalogger_dataloggersettings;
 id |   com_port   | dsmr_version
----+--------------+--------------
  1 | /dev/ttyUSB0 |            4
(1 row)

dennissiemensma commented 4 years ago

Ik denk dat je het beste eerst debug-logging kunt inschakelen en dan kijken in de log van de dsmr_backend waar die op hangt: https://dsmr-reader.readthedocs.io/nl/latest/troubleshooting.html#logging

Ik vermoed dat hij stopt omdat die nog een gasmeting verwacht. Als dat zo is, zal ik die check wat moeten verbeteren.

dennissiemensma commented 4 years ago

Waarschijnlijk komt er bij debugging dan deze melding in je logs: Stats: Waiting for first gas reading on the next day...

swerveshot commented 4 years ago

Helemaal correct!

[2020-01-02 23:25:33,874] DEBUG    Compact: Waiting for newer readings before grouping data...
[2020-01-02 23:25:35,459] DEBUG    dsmr_backend.management.commands.dsmr_backend: Sleeping 1s
[2020-01-02 23:25:36,521] DEBUG    SP: 1 backend service(s) ready to run
[2020-01-02 23:25:36,522] DEBUG    SP: Running "Generate day and hour statistics" (dsmr_stats.services.run)
[2020-01-02 23:25:36,704] DEBUG    Stats: Waiting for first gas reading on the next day...
[2020-01-02 23:25:36,721] DEBUG    SP: Rescheduled "Generate day and hour statistics" to 2020-01-02 23:30:36.705230+01:00 (ETA 0:04:59.983536)
[2020-01-02 23:25:36,743] DEBUG    Compact: Waiting for newer readings before grouping data...
[2020-01-02 23:25:38,145] DEBUG    dsmr_backend.management.commands.dsmr_backend: Sleeping 1s
[2020-01-02 23:25:39,210] DEBUG    SP: 0 backend service(s) ready to run

Een nadeel is alleen dat nu m'n dsmr_webinterface in een start loop zit. Ook nadat ik de debug logging weer uit-gecomment heb. Morgen maar eens kijken waar dat nu weer aan ligt.

swerveshot commented 4 years ago

Oei van de regen in de drup. Nu krijg ik de web frontend niet meer aan de gang terwijl ik andres dan de debug instellingen aan- en weer uitzetten niets heb gedaan (gevolgd door een post-deploy.sh natuurlijk). De dsmr_webinterface supervisor logging toont dit in een loop:

[2020-01-02 23:53:57 +0100] [4858] [INFO] Starting gunicorn 19.7.0
[2020-01-02 23:53:57 +0100] [4858] [ERROR] Retrying in 1 second.
[2020-01-02 23:53:58 +0100] [4858] [ERROR] Retrying in 1 second.
[2020-01-02 23:53:59 +0100] [4858] [ERROR] Retrying in 1 second.
[2020-01-02 23:54:00 +0100] [4858] [ERROR] Retrying in 1 second.
[2020-01-02 23:54:01 +0100] [4858] [ERROR] Retrying in 1 second.
[2020-01-02 23:54:02 +0100] [4858] [ERROR] Can't connect to /var/tmp/gunicorn--dsmr_webinterface.socket

Suggesties?

dennissiemensma commented 4 years ago

Om het issue met de gasmetingen op te lossen, zal ik een wijziging moeten doorvoeren.

Voor je issue met de frontend kun je het beste even een harde reset doen met git reset --hard en dan een nieuwe deploy.

dennissiemensma commented 4 years ago

Als workaround kun je ervoor kiezen om gas helemaal uit te schakelen in de applicatie: https://dsmr-reader.readthedocs.io/en/latest/settings.html#dsmrreader-disabled-capabilities

Nadeel is dan wel dat je dan vermoedelijk nergens in de applicatie meer gasmetingen ziet van je vorige woning.

dennissiemensma commented 4 years ago

Ik heb een fix gemaakt in de development branch. Als de tests klaar zijn met draaien en OK zijn, kun je updaten: https://circleci.com/workflow-run/414dc8aa-0f92-40bc-91f4-001717474ea2

swerveshot commented 4 years ago

Many thanks @dennissiemensma! Ik ga er morgen even rustig voor zitten. Want als ik - zoals je voorstelde - een herinstallatie moet doen dan ben ik wel even bezig. Het is gewoon kwestie van oude virtualenv ergens parkeren en dan opnieuw beginnen toch? De CI geeft in ieder geval groen licht. ✔️

dennissiemensma commented 4 years ago

Ik bedoel dat je gewoon ./deploy.sh kunt draaien voor de fix. Herinstallatie lijkt me niet nodig als de rest gewoon goed werkt.

swerveshot commented 4 years ago

De fix lijkt z'n werk gedaan te hebben. Good job! 👏🏻

dsmrreader=# select hour_start from dsmr_stats_hourstatistics order by hour_start desc limit 10;
       hour_start
------------------------
 2020-01-03 23:00:00+01
 2020-01-03 22:00:00+01
 2020-01-03 21:00:00+01
 2020-01-03 20:00:00+01
 2020-01-03 19:00:00+01
 2020-01-03 18:00:00+01
 2020-01-03 17:00:00+01
 2020-01-03 15:00:00+01
 2020-01-03 14:00:00+01
 2020-01-03 13:00:00+01
(10 rows)

dsmrreader=# select day from dsmr_stats_daystatistics order by day desc limit 10;
    day
------------
 2020-01-03
 2020-01-02
 2020-01-01
 2019-12-31
 2019-12-30
 2019-12-29
 2019-12-28
 2019-12-27
 2019-12-26
 2019-12-25
(10 rows)

De web interface blijft echter wel nukkig. Dus tenzij je daarvoor nog een goede tip hebt wordt het toch even opnieuw installeren.

dennissiemensma commented 4 years ago

Je kunt kijken of je hier ook een foutmelding krijgt:

sudo su - dsmr
/home/dsmr/.virtualenvs/dsmrreader/bin/gunicorn dsmrreader.wsgi

Je kunt die rustig met CTRL+C afbreken.

swerveshot commented 4 years ago

Yup, ook hier een foutmeling.

(dsmrreader) dsmr@odroid:~/dsmr-reader$ /home/dsmr/.virtualenvs/dsmrreader/bin/gunicorn dsmrreader.wsgi
[2020-01-04 13:47:04 +0100] [32160] [INFO] Starting gunicorn 19.7.0
[2020-01-04 13:47:04 +0100] [32160] [ERROR] Retrying in 1 second.
[2020-01-04 13:47:05 +0100] [32160] [ERROR] Retrying in 1 second.
[2020-01-04 13:47:06 +0100] [32160] [ERROR] Retrying in 1 second.
[2020-01-04 13:47:07 +0100] [32160] [ERROR] Retrying in 1 second.
[2020-01-04 13:47:08 +0100] [32160] [ERROR] Retrying in 1 second.
[2020-01-04 13:47:09 +0100] [32160] [ERROR] Can't connect to ('127.0.0.1', 8000)

Firewall heb ik voor de zekerheid even helemaal uitgezet, maar dat maakte niets uit.

dennissiemensma commented 4 years ago

Werkt dit wel?

sudo su - dsmr
./manage.py runserver

swerveshot commented 4 years ago

Ja, dat dan weer wel.

(dsmrreader) dsmr@odroid:~/dsmr-reader$ ./manage.py runserver
Performing system checks...

System check identified no issues (0 silenced).
January 04, 2020 - 18:48:38
Django version 2.2.9, using settings 'dsmrreader.settings'
Starting development server at http://127.0.0.1:8000/
Quit the server with CONTROL-C.

dennissiemensma commented 4 years ago

En eerder werkte Gunicorn, de webinterface, dus wel gewoon zonder problemen?
Staat er verder niets extra's in /var/log/supervisor/dsmr_webinterface.log?
Je zou nog kunnen kijken of er iets gerelateerd staat in /var/log/syslog.

dennissiemensma commented 4 years ago

Ik sluit het oorspronkelijke issue even voor de release, maar comment gerust verder als je nog meer info hebt.

swerveshot commented 4 years ago

Geen probleem hoor. Snap ook dat je een nieuwe release eruit wil hebben. Ik rommel nog wel even verder. Hartelijk dank in ieder geval. 🙏🏻

dsmrreader / dsmr-reader