Na een stroom storing worden oude gegevens niet ingelezen. #1457

vincentweeda · 2021-09-15T16:17:56Z

vincentweeda
Sep 15, 2021

Beste,

Op 14/09 is mijn aardlek er uitgesprongen hierdoor kwam de raspberry uiteraard zonder stroom te zitten.
Echter is mijn externe database beschermd doormiddel van een UPS.

Nu viel mij op dat de Too many unprocessed readings rond de 218-19 blijft hangen, en dat enkel de nieuwste waardes worden verwerkt.

In de debug logging zie ik geen fouten of andere info wat op een database issue kan duiden. Ook de database server zelf na een automatishe repair actie geeft geen foutmeldigen meer.

Is het mogelijk om de de oude telegrammen te forceren of wellicht weg te gooien zonder dat dit voor data verlies kan leiden?

Thanks!


DSMR-READER (Raspbian, Raspberry 3b+)
    App / Python / Database                                                     v4.16.3 / v3.7.3 / postgresql
    BE sleep / DL sleep / Retention / Override                                     1.0s / 5.0s / 168h / False
    Latest telegram version read / Parser settings                                                 "42" / "4"

DATA
    Telegrams total (est.)                                                                              59876
    Consumption records electricity / gas (est.)                                                   9905 / 113

UNRESOLVED ISSUES
    Too many unprocessed readings: 217                                                         25 seconds ago

Database server: postgres (PostgreSQL) 10.17
Database server OS: Redhat Linux 8

**==> /var/log/supervisor/dsmr_backend.log <==**
2021-09-15 17:21:45,774 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:45,804 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-09-15 17:21:46,815 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:46,842 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-09-15 17:21:47,853 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:47,880 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-09-15 17:21:48,890 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:48,916 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s
2021-09-15 17:21:49,927 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:49,955 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

**==> /var/log/supervisor/dsmr_datalogger.log <==**
Current logging level set to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/latest/how-to/troubleshooting/enabling-debug-logging.html

**==> /var/log/supervisor/dsmr_datalogger-stderr---supervisor-WuFywi.log <==**

2021-09-15 17:21:43,404 DEBUG    mixins       run_loop                         73 | dsmr_datalogger.management.commands.dsmr_datalogger: Sleeping 5.0s
2021-09-15 17:21:48,417 INFO     dsmr_datalogger_api_client read_telegram                    30 | [2021-09-15 17:21:48.417137] Opening connection "/dev/ttyUSB0" using options: {'baudrate': 115200, 'bytesize': 8, 'parity': 'N', 'stopbits': 1, 'xonxoff': 1, 'rtscts': 0}
2021-09-15 17:21:48,755 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:48.755331] Read 0 Byte(s)
2021-09-15 17:21:49,090 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:49.090030] Read 0 Byte(s)
2021-09-15 17:21:49,424 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:49.424650] Read 0 Byte(s)
2021-09-15 17:21:49,759 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:49.759317] Read 0 Byte(s)
2021-09-15 17:21:50,094 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:50.094004] Read 0 Byte(s)

**==> /var/log/supervisor/dsmr_webinterface.log <==**
[2021-09-15 17:21:14 +0200] [789] [INFO] Worker exiting (pid: 789)
[2021-09-15 17:21:14 +0200] [791] [INFO] Worker exiting (pid: 791)
[2021-09-15 17:21:16 +0200] [784] [INFO] Shutting down: Master
[2021-09-15 17:21:20 +0200] [2692] [INFO] Starting gunicorn 20.1.0
[2021-09-15 17:21:20 +0200] [2692] [INFO] Listening at: unix:/var/tmp/gunicorn--dsmr_webinterface.socket (2692)
[2021-09-15 17:21:20 +0200] [2692] [INFO] Using worker: sync
[2021-09-15 17:21:20 +0200] [2697] [INFO] Booting worker with pid: 2697
[2021-09-15 17:21:20 +0200] [2698] [INFO] Booting worker with pid: 2698
[2021-09-15 17:21:20 +0200] [2699] [INFO] Booting worker with pid: 2699
[2021-09-15 17:21:20 +0200] [2700] [INFO] Booting worker with pid: 2700

**==> /var/log/supervisor/supervisord.log <==**
2021-09-15 17:21:16,559 INFO stopped: dsmr_webinterface (exit status 0)
2021-09-15 17:21:16,602 INFO stopped: dsmr_backend (exit status 0)
2021-09-15 17:21:17,605 INFO waiting for dsmr_datalogger to stop
2021-09-15 17:21:19,051 INFO stopped: dsmr_datalogger (exit status 0)
2021-09-15 17:21:19,069 INFO spawned: 'dsmr_webinterface' with pid 2692
2021-09-15 17:21:19,075 INFO spawned: 'dsmr_datalogger' with pid 2693
2021-09-15 17:21:19,082 INFO spawned: 'dsmr_backend' with pid 2694
2021-09-15 17:21:20,086 INFO success: dsmr_datalogger entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2021-09-15 17:21:20,108 INFO success: dsmr_backend entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2021-09-15 17:21:22,256 INFO success: dsmr_webinterface entered RUNNING state, process has stayed up for > than 3 seconds (startsecs)

**==> /var/log/supervisor/dsmr_datalogger-stderr---supervisor-WuFywi.log <==**
2021-09-15 17:21:50,428 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:50.428558] Read 0 Byte(s)
2021-09-15 17:21:50,763 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:50.763159] Read 0 Byte(s)

**==> /var/log/supervisor/dsmr_backend.log <==**
2021-09-15 17:21:50,966 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:50,997 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

**==> /var/log/supervisor/dsmr_datalogger-stderr---supervisor-WuFywi.log <==**
2021-09-15 17:21:51,099 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:51.099250] Read 0 Byte(s)
2021-09-15 17:21:51,433 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:51.433847] Read 0 Byte(s)
2021-09-15 17:21:51,768 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:51.768695] Read 0 Byte(s)

==> /var/log/supervisor/dsmr_backend.log <==
2021-09-15 17:21:52,008 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:52,037 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

**==> /var/log/supervisor/dsmr_datalogger-stderr---supervisor-WuFywi.log <==**
2021-09-15 17:21:52,103 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:52.103652] Read 0 Byte(s)
2021-09-15 17:21:52,438 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:52.438169] Read 217 Byte(s)
2021-09-15 17:21:52,772 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:52.772653] Read 215 Byte(s)

==> /var/log/supervisor/dsmr_backend.log <==
2021-09-15 17:21:53,047 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:53,074 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

**==> /var/log/supervisor/dsmr_datalogger-stderr---supervisor-WuFywi.log <==**
2021-09-15 17:21:53,107 DEBUG    dsmr_datalogger_api_client read_telegram                    51 | [2021-09-15 17:21:53.107123] Read 193 Byte(s)
2021-09-15 17:21:53,117 DEBUG    datalogger   telegram_to_reading              74 | Received telegram:
/KFM5KAIFA-METER

De rest  van het telegram

2021-09-15 17:21:53,217 DEBUG    mixins       run_loop                         73 | dsmr_datalogger.management.commands.dsmr_datalogger: Sleeping 5.0s

**==> /var/log/supervisor/dsmr_backend.log <==**
2021-09-15 17:21:54,084 DEBUG    schedule     execute_scheduled_processes      28 | SP: 0 backend service(s) ready to run
2021-09-15 17:21:54,111 DEBUG    mixins       run_loop                         73 | dsmr_backend.management.commands.dsmr_backend: Sleeping 1.0s

Answered by vincentweeda

Sep 16, 2021

Ok, ik ben er achter wat het probleem was... en het was makkelijker dan gedacht.

De tijd op mijn raspberry lag 10 minuten vroeger dan de tijd op de de database server en mijn laptop.

Ik heb de tijd hersteld en weer in-sync gebracht (geen idee waarom het gebeurt is) en nu loopt ie op tot 6-7 en daarna worden ook de meldingen weer op de juiste verwerkt.

Het resultaat nu:

dsmrreader=# select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false order by timestamp desc;
  id   |       timestamp        | processed 
-------+------------------------+-----------
 77690 | 2021-09-16 17:00:08+02 | f
 77689 | 2021-09-16 16:59:58+02 | f
 77688 | 2021-09-16 16:59:48+02 | f
…

View full answer

dennissiemensma · 2021-09-15T19:11:38Z

dennissiemensma
Sep 15, 2021
Maintainer

Bedankt voor je melding. Het makkelijkste is om te kijken waar die onverwerkte telegrammen hangen (als je nog niet zo diep had gekeken). En dus of het een aantal oude telegrammen zijn, of dat er een soort lag is.

sudo su - postgres
psql dsmrreader

select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false order by timestamp desc;

Ik krijg zoiets:

    id    |       timestamp        | processed 
----------+------------------------+-----------
 16496353 | 2021-09-15 20:06:38+01 | f
 16496352 | 2021-09-15 20:06:18+01 | f
(2 rows)

In jouw geval zou je alle 200 moeten zien, aflopend op nieuwste bovenaan. Wat zie je daar voor trends? Zijn ze allemaal recent?

0 replies

dennissiemensma · 2021-09-15T19:21:47Z

dennissiemensma
Sep 15, 2021
Maintainer

Mochten het trouwens echt een aantal oude telegrammen zijn die niet verwerkt worden (zou niet moeten voorkomen overigens), dan kun je ze het beste met een select-query isoleren (checken of de selectie goed is) en daarna updaten.

Bijvoorbeeld alles van voor 20:00:00 vandaag wat nu nog niet verwerkt is:

select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false and timestamp < '2021-09-15 20:00:00+01'

Dubbelcheck of die query alleen degene teruggeeft die je wilt sluiten.

Zo ja, voer dan dezelfde query, in update vorm uit:

update dsmr_datalogger_dsmrreading set processed = true where processed = false and timestamp < '2021-09-15 20:00:00+01';

Daarna zou de eerdere select-query geen resultaten meer moeten geven.

Bovenstaande gaat dus niet helpen als er consequent een vertraging zit in de verwerking, waardoor er telkens 200+ onverwerkt blijven. Dan zullen we verder moeten debuggen.

0 replies

vincentweeda · 2021-09-16T14:41:29Z

vincentweeda
Sep 16, 2021
Author

In jouw geval zou je alle 200 moeten zien, aflopend op nieuwste bovenaan. Wat zie je daar voor trends? Zijn ze allemaal recent?

De enige trend die ik zie is dat ze allemaal recent zijn van het laatste uur, en elke 10 seconde komt er een nieuw item binnen.
Ik en dus bang dat de onderstaande oplossing in deze niet gaat werken, of heb ik dat mis?

dsmrreader=# select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false order by timestamp desc;
  id   |       timestamp        | processed 
-------+------------------------+-----------
 77539 | 2021-09-16 16:34:49+02 | f
 77538 | 2021-09-16 16:34:39+02 | f
 77537 | 2021-09-16 16:34:29+02 | f
 77536 | 2021-09-16 16:34:19+02 | f
 77535 | 2021-09-16 16:34:10+02 | f
 77534 | 2021-09-16 16:34:00+02 | f
 77533 | 2021-09-16 16:33:50+02 | f
 77532 | 2021-09-16 16:33:40+02 | f

EDIT:
Ik heb onder het motto alles vooronderzoek, alles voor 16:30 gesloten, ik hou het even in de gaten of het nu Ok blijft of niet.

0 replies

vincentweeda · 2021-09-16T15:02:20Z

vincentweeda
Sep 16, 2021
Author

Ok, ik ben er achter wat het probleem was... en het was makkelijker dan gedacht.

De tijd op mijn raspberry lag 10 minuten vroeger dan de tijd op de de database server en mijn laptop.

Ik heb de tijd hersteld en weer in-sync gebracht (geen idee waarom het gebeurt is) en nu loopt ie op tot 6-7 en daarna worden ook de meldingen weer op de juiste verwerkt.

Het resultaat nu:

dsmrreader=# select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false order by timestamp desc;
  id   |       timestamp        | processed 
-------+------------------------+-----------
 77690 | 2021-09-16 17:00:08+02 | f
 77689 | 2021-09-16 16:59:58+02 | f
 77688 | 2021-09-16 16:59:48+02 | f
 77687 | 2021-09-16 16:59:39+02 | f
 77686 | 2021-09-16 16:59:29+02 | f
 77685 | 2021-09-16 16:59:19+02 | f
 77684 | 2021-09-16 16:59:09+02 | f
(7 rows)

dsmrreader=# select id, timestamp, processed from dsmr_datalogger_dsmrreading where processed = false order by timestamp desc;
  id   |       timestamp        | processed 
-------+------------------------+-----------
 77690 | 2021-09-16 17:00:08+02 | f
(1 row)

Dus pro tip ook voor mij zelf.. zorg dat de tijd goed staat dat bespaard een hoop gezeur 👍

0 replies

dennissiemensma · 2021-09-16T19:47:11Z

dennissiemensma
Sep 16, 2021
Maintainer

Bedankt voor je update, fijn dat je het zelf al zo snel gevonden hebt!

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Na een stroom storing worden oude gegevens niet ingelezen. #1457

{{title}}

Replies: 5 comments

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

Na een stroom storing worden oude gegevens niet ingelezen. #1457

vincentweeda Sep 15, 2021

Replies: 5 comments

dennissiemensma Sep 15, 2021 Maintainer

dennissiemensma Sep 15, 2021 Maintainer

vincentweeda Sep 16, 2021 Author

vincentweeda Sep 16, 2021 Author

dennissiemensma Sep 16, 2021 Maintainer

vincentweeda
Sep 15, 2021

dennissiemensma
Sep 15, 2021
Maintainer

dennissiemensma
Sep 15, 2021
Maintainer

vincentweeda
Sep 16, 2021
Author

vincentweeda
Sep 16, 2021
Author

dennissiemensma
Sep 16, 2021
Maintainer