⚠️ Docker only - Reading timestamp differences (1 or 2 hours off)

[8uurg]

Oplossing

Verwijder deze mount:

/etc/localtime:/etc/localtime:ro

Alternatief

Gebruik postgres:12.4-alpine

https://github.com/dsmrreader/dsmr-reader/issues/1282#issuecomment-778618994

---

Oorspronkelijk issue:

Server error tussen 23:00 en 00:00: LookupError: No electricity readings found for: 2021-02-11

Omgeving Ik draai DSMR reader in Docker, met een remote datalogger.

DSMR-READER
    App / Python / Database                                                       v4.11 / v3.9.1 / postgresql
    BE sleep / DL sleep / Retention / Override                                     1.0s / 5.0s / 672h / False
    Latest telegram version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                             209017
    Consumption records electricity / gas (est.)                                                 38752 / 8479

UNRESOLVED ISSUES
    Too many unprocessed readings: 1937                                                          a minute ago

(voor unprocessed readings heb ik de reportagesnelheid al op 5s gezet, ipv de standaardwaarde van 0.5s.)

Probleemomschrijving Na terugzetten van een backup probeert DSMR na opstarten herhaaldelijk rijen toe te voegen waarin waardes voorkomen met null:

dsmrdb_1  | 2021-02-10 22:29:00.344 CET [38] ERROR:  null value in column "delivered_1" violates not-null constraint
dsmrdb_1  | 2021-02-10 22:29:00.344 CET [38] DETAIL:  Failing row contains (70779, 2021-02-09 04:00:00+01, null, null, null, null, null, null, null, null, null, null, null, null, null, null, null, null, null, null).
dsmrdb_1  | 2021-02-10 22:29:00.344 CET [38] STATEMENT:  INSERT INTO "dsmr_consumption_electricityconsumption" ("read_at", "delivered_1", "returned_1", "delivered_2", "returned_2", "currently_delivered", "currently_returned", "phase_currently_delivered_l1", "phase_currently_delivered_l2", "phase_currently_delivered_l3", "phase_currently_returned_l1", "phase_currently_returned_l2", "phase_currently_returned_l3", "phase_voltage_l1", "phase_voltage_l2", "phase_voltage_l3", "phase_power_current_l1", "phase_power_current_l2", "phase_power_current_l3") VALUES ('2021-02-09T03:00:00+00:00'::timestamptz, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL, NULL) RETURNING "dsmr_consumption_electricityconsumption"."id"

Dit herhaalt zich zo ongeveer iedere 30s, ondertussen update de live grafiek niet.

Verder heb ik tussen 23:00 en 24:00 geen toegang tot het dashboard en krijg ik het volgende bericht (om 23:18):

Server Error
Sorry, something unexpected happened.
Exception:

LookupError: No electricity readings found for: 2021-02-11

Traceback:

  File "/usr/local/lib/python3.9/site-packages/django/core/handlers/base.py", line 181, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)

  File "/usr/local/lib/python3.9/site-packages/django/views/generic/base.py", line 70, in view
    return self.dispatch(request, *args, **kwargs)

  File "/dsmr/dsmr_frontend/mixins.py", line 11, in dispatch
    return super().dispatch(request, *args, **kwargs)

  File "/usr/local/lib/python3.9/site-packages/django/views/generic/base.py", line 98, in dispatch
    return handler(request, *args, **kwargs)

  File "/usr/local/lib/python3.9/site-packages/django/views/generic/base.py", line 159, in get
    context = self.get_context_data(**kwargs)

  File "/dsmr/dsmr_frontend/views/dashboard.py", line 31, in get_context_data
    context_data['consumption'] = dsmr_consumption.services.day_consumption(

  File "/dsmr/dsmr_consumption/services.py", line 248, in day_consumption
    raise LookupError("No electricity readings found for: {}".format(day))

Kanttekening Voor als iemand anders dit tegenkomt: Ik heb dit kort opgelost door de constraints uit de tabellen te verwijderen

START TRANSACTION;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN delivered_1 DROP NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN delivered_2 DROP NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN returned_1 DROP NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN returned_2 DROP NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN currently_delivered DROP NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN currently_returned DROP NOT NULL;
COMMIT;

Om de rijen toegevoegd te laten worden, om ze vervolgens weer te verwijderen:

DELETE FROM dsmr_consumption_electricityconsumption WHERE delivered_1 IS NULL;

En de constraints weer teruggezet:

START TRANSACTION;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN delivered_1 SET NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN delivered_2 SET NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN returned_1 SET NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN returned_2 SET NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN currently_delivered SET NOT NULL;
ALTER TABLE dsmr_consumption_electricityconsumption ALTER COLUMN currently_returned SET NOT NULL;
COMMIT;

Voor het laatste probleem heb ik echter geen oplossing... De datum en tijd in de containers (dsmr en db) zijn correct.

[8uurg]

Zelfde hier, aanpassen van de timezone van de DB helpt niet... Behalve dat ik weer nulls binnenkrijg...

[dennissiemensma]

Verandert de output van /var/lib/postgresql/data/postgresql.conf ook als jullie de tijdzone vars aanpassen van de DB?

[8uurg]

Nee, hij gebruikt de envvars alleen bij initiele setup. Moest conf handmatig bewerken:

root@3b2b901db476:/# grep timezone /var/lib/postgresql/data/postgresql.conf
log_timezone = 'Europe/Amsterdam'
timezone = 'Europe/London'
#timezone_abbreviations = 'Default'     # Select the set of available time zone
                                        # share/timezonesets/.

[dennissiemensma]

Oke. Misschien wel goed om ook log_timezone op Europe/London te zetten voor de zekerheid. En dan ben ik benieuwd wat die dan doet na een herstart.

[Tralapo]

Met timezone op Amsterdam:

root@53e081077ba0:/# grep timezone /var/lib/postgresql/data/postgresql.conf
log_timezone = 'Europe/Amsterdam'
timezone = 'Europe/Amsterdam'
#timezone_abbreviations = 'Default'     # Select the set of available time zone
                                        # share/timezonesets/.

Met timezone op London, geeft 'ie ook Amsterdam?

root@8a234c6ac89c:/# grep timezone /var/lib/postgresql/data/postgresql.conf
log_timezone = 'Europe/Amsterdam'
timezone = 'Europe/Amsterdam'
#timezone_abbreviations = 'Default'     # Select the set of available time zone
                                        # share/timezonesets/.

Date klopt wel met London:

root@8a234c6ac89c:/# date
Thu 11 Feb 2021 10:24:05 PM GMT

[dennissiemensma]

@Tralapo ik begrijp net dat die alleen bij installatie eenmalig gebruikt wordt. Vandaar en dat verklaart ook mogelijk waarom jullie geen verschil zien als je het aanpast naar een andere tijdzone op de DB.

Dus ik ben benieuwd of het uiteindelijk wel werkt als DSMR-reader Europe/Amsterdam heeft en de twee tijdzones in /var/lib/postgresql/data/postgresql.conf op Europe/London. (Na een herstart)

[8uurg]

Oke. Misschien wel goed om ook log_timezone op Europe/London te zetten voor de zekerheid. En dan ben ik benieuwd wat die dan doet na een herstart.

dsmrdb_1  | 2021-02-11 22:23:53.028 GMT [1] LOG:  starting PostgreSQL 12.5 (Debian 12.5-1.pgdg100+1) on arm-unknown-linux-gnueabihf, compiled by gcc (Debian 8.3.0-6) 8.3.0, 32-bit
dsmrdb_1  | 2021-02-11 22:23:53.028 GMT [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
dsmrdb_1  | 2021-02-11 22:23:53.028 GMT [1] LOG:  listening on IPv6 address "::", port 5432
[ INFO ] Verifying if the DSMR web credential variables have been set...
[ INFO ] Verifying Database connectivity...
dsmrdb_1  | 2021-02-11 22:23:53.040 GMT [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
dsmrdb_1  | 2021-02-11 22:23:53.105 GMT [26] LOG:  database system was shut down at 2021-02-11 22:23:04 GMT
dsmrdb_1  | 2021-02-11 22:23:53.128 GMT [1] LOG:  database system is ready to accept connections

Helaas verandert ook dit niets (behalve dat de tijd nu in GMT is)... Ik vraag me af wat voor vreemd iets er tussen PostgreSQL en Django afspeelt, want het model geeft een andere waarde dan wat er in de database staat.

[Tralapo]

@Tralapo ik begrijp net dat die alleen bij installatie eenmalig gebruikt wordt. Vandaar en dat verklaart ook mogelijk waarom jullie geen verschil zien als je het aanpast naar een andere tijdzone op de DB.

Ik dacht dat een docker-container altijd gold als een nieuwe installatie als je hem down had gehaald, maar blijkbaar niet dan?

Dus ik ben benieuwd of het uiteindelijk wel werkt als DSMR-reader Europe/Amsterdam heeft en de twee tijdzones in /var/lib/postgresql/data/postgresql.conf op Europe/London. (Na een herstart)

Het lukt mij niet om dat bestand te wijzigen binnen de container, weet jij hoe dat eventueel kan @8uurg? sudo docker exec -it dsmrdb bash en daarna met nano of vi kan niet.

Lol, het is letterlijk apt-get install nano. Enfin. Gewijzigd in Europe/London en opnieuw opgestart. Met DSMR nog op Amsterdam levert dat nog steeds dezelfde foutmelding op en is DSMR onbereikbaar @dennissiemensma.

[dennissiemensma]

Jullie zouden nog de Django shell kunnen proberen en kijken wat dit teruggeeft:

./manage.py shell

from django.db import connection
with connection.cursor() as cursor:
    cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
    cursor.fetchall()

# 2x Enter voor resultaat

En:

./manage.py shell

from django.db import connection
with connection.cursor() as cursor:
    cursor.execute('show timezone')
    cursor.fetchall()

# 2x Enter voor resultaat

---

Update: Als voorbeeld, wordt het bij mij zoiets en dat lijkt te kloppen:

>>> from django.db import connection
>>> with connection.cursor() as cursor:
...     cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
...     cursor.fetchall()
... 
[(datetime.datetime(2021, 2, 12, 19, 22, 26, tzinfo=<UTC>),)]

>>> from django.db import connection
>>> with connection.cursor() as cursor:
...    cursor.execute('show timezone')
...    cursor.fetchall()
... 
[('UTC',)]

[dennissiemensma]

Ik hoor het wel. Morgen weer een nieuwe dag, maar veel opties blijven niet over zo.

[Tralapo]

Dat geeft:

>>> with connection.cursor() as cursor:
...     cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
...     cursor.fetchall()
...
[(datetime.datetime(2021, 2, 11, 23, 45, 24, tzinfo=<UTC>),)]

En

>>> from django.db import connection
>>> with connection.cursor() as cursor:
...     cursor.execute('show timezone')
...     cursor.fetchall()
...
[('UTC',)]

[xirixiz]

De output voor mij is identiek vanuit Docker:

-> docker exec -ti dsmrdb bash
bash-5.1# grep timezone /var/lib/postgresql/data/postgresql.conf
log_timezone = 'Europe/Amsterdam'
timezone = 'Europe/Amsterdam'

Verder zet ik alleen TZ=Europe/Amsterdam op zowel de PG als DSMR container. That's it. Ik gebruik geen PG_TZ en/of DJANGO_TIMEZONE.

Belangrijke toevoeging is nog dat ik /etc/localtime:ro mount in de zowel de PG als DSMR container.

Wel vreemd dat dit probleem ineens ontstaat. Vanuit Alpine Docker vwb Postgres weet ik dat er problemen zijn met rechten, maar dat is bij iedereen opgelost door niet meer het Postgres Alpine image te gebruiken.

Hoe ziet jullie setup eruit wat host/hardware betreft? Welke Docker versie?

[Tralapo]

Raspberry:

Hardware        : BCM2835
Revision        : a02082
Serial          : 000000007d63a05c
Model           : Raspberry Pi 3 Model B Rev 1.2

Raspbian:

pi@raspberrypi:[~] cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Docker:

pi@raspberrypi:[~] docker -v
Docker version 20.10.3, build 48d30b5

Docker-compose:

pi@raspberrypi:[~] docker-compose -v
docker-compose version 1.27.4, build unknown

Docker-compose file:

### DSMR Database en Reader ###
  dsmrdb:
    image: postgres:12
    container_name: dsmrdb
    restart: always
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - ./data/dsmrdb:/var/lib/postgresql/data
    environment:
      - TZ=Europe/Amsterdam
      - PG_TZ=Europe/Amsterdam
      - POSTGRES_USER=dsmrreader
      - POSTGRES_PASSWORD=dsmrreader
      - POSTGRES_DB=dsmrreader

  dsmr:
    image: xirixiz/dsmr-reader-docker:latest
    container_name: dsmr
    depends_on:
      - dsmrdb
    cap_add:
      - NET_ADMIN
    restart: always
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - ./data/dsmr_backups:/dsmr/backups
      - ./data/dsmr_logs:/var/log/supervisor
    environment:
      - DJANGO_TIME_ZONE=Europe/Amsterdam
      - VIRTUAL_HOST=localhost
    ports:
      - 7777:80
      - 7779:443
    devices:
      - /dev/ttyUSB0:/dev/ttyUSB0

@xirixiz die DJANGO_TIME_ZONE en PG_TZ zitten erin omdat je die in je eigen repo ook opgenomen hebt in de docker-compose.example

[xirixiz]

Het Docker deel ziet er goed uit, niets bijzonders. Nu ben ik benieuwd hoe de setup er van @8uurg eruit ziet. Wanneer dat identiek is, zit wellicht daar ergens de oorzaak.

De vars komen hier vandaan vwb DJANGO: https://dsmr-reader.readthedocs.io/en/v4/env_settings.html

[8uurg]

@dennissiemensma Hierbij de uitvoer van de commandos, de tijd klopt niet: het is op dit moment namelijk 9:28, Nederlandse tijd, niet UTC.

bash-5.0# ./manage.py shell
Python 3.9.1 (default, Dec 17 2020, 06:29:58)
[GCC 9.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
>>> from django.db import connection
>>> with connection.cursor() as cursor:
...    cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
...    cursor.fetchall()
[(datetime.datetime(2021, 2, 12, 9, 28, 35, tzinfo=<UTC>),)]
>>> from django.db import connection
>>> with connection.cursor() as cursor:
...    cursor.execute('show timezone')
...    cursor.fetchall()
[('UTC',)]

Edit: Ter aanvulling, via psql (om 9:42, Nederlandse tijd)

dsmrreader=# SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1;
       timestamp
------------------------
 2021-02-12 08:41:50+00
(1 row)

Zelfde gebeurt voor SELECT NOW();:

bash-5.0# ./manage.py shell
Python 3.9.1 (default, Dec 17 2020, 06:29:58)
[GCC 9.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
>>> from django.db import connection
>>> with connection.cursor() as cursor:
...     cursor.execute('SELECT NOW();')
...     cursor.fetchall()
...
[(datetime.datetime(2021, 2, 12, 9, 49, 55, 615137, tzinfo=<UTC>),)]

Via psql:

dsmrreader=# SELECT NOW();
              now
-------------------------------
 2021-02-12 08:50:49.839681+00
(1 row)

Als ik met psycopg2 werk vanuit de dsmr container gaat het (in tegenstelling tot via django.db) wel goed:

>>> conn = psycopg2.connect("host=dsmrdb dbname=dsmrreader user=dsmrreader password=<snip>")
>>> cur = conn.cursor()
>>> cur.execute("SELECT NOW();")
>>> cur.fetchall()
[(datetime.datetime(2021, 2, 12, 15, 18, 46, 908835, tzinfo=psycopg2.tz.FixedOffsetTimezone(offset=0, name=None)),)]

Verder, als ik de tijdzone om de data in terug te geven expliciet vermeld gaat het ook goed via Django:

>>> with connection.cursor() as cur:
...     cur.execute("SELECT (NOW() AT TIME ZONE 'UTC')::timestamptz;")
...     cur.fetchall()
...
[(datetime.datetime(2021, 2, 12, 15, 53, 39, 585524, tzinfo=<UTC>),)]

@xirixiz Hierbij mijn docker compose file voor dsmr:

version: '3.8'

services:
  dsmrdb:
    image: postgres:12
    restart: unless-stopped
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - ./db:/var/lib/postgresql/data
    environment:
      - TZ=Europe/London
      - PG_TZ=Europe/London
      - POSTGRES_USER=dsmrreader
      - POSTGRES_PASSWORD=<snip>
      - POSTGRES_DB=dsmrreader

  mqtt:
    image: eclipse-mosquitto:2
    restart: unless-stopped
    volumes:
      - ./mosquitto.conf:/mosquitto/config/mosquitto.conf
      - ./mosquitto_passwords.txt:/mosquitto/passwords
    ports:
      - 1883:1883
      - 9001:9001

  dsmr:
    image: xirixiz/dsmr-reader-docker:latest
    depends_on:
      - dsmrdb
      - mqtt
    cap_add:
      - NET_ADMIN
    restart: unless-stopped
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - ./dsmr_backups:/dsmr/backups
    environment:
      - DATALOGGER_MODE=receiver
      - DJANGO_TIME_ZONE=Europe/Amsterdam
      - DJANGO_DATABASE_PASSWORD=<snip>
      - DSMRREADER_ADMIN_USER=<snip>
      - DSMRREADER_ADMIN_PASSWORD=<snip>
      - VIRTUAL_HOST=localhost
    ports:
      - 8284:80
    #devices:
    #  - /dev/ttyUSB0:/dev/ttyUSB0

[Tralapo]

Naast DSMR draai ik op dezelfde Pi ook Home Assistant in een container. Daarmee las ik ook altijd de meterstanden en huidige verbruik/oplevering uit via MQTT. Dat werkt ook niet meer sinds de boel in de soep liep.

Geen idee of, dan wel hoe het raakvlakken heeft met de tijd-bug, maar het is wel op hetzelfde moment ontstaan. Met logging op DEBUG zegt dsmr_backend.log er dit over:

[2021-02-12 15:21:27,048] DEBUG    MQTT: Initializing MQTT client for "192.168.1.20:1883"
[2021-02-12 15:21:27,051] DEBUG    MQTT: Using insecure connection (no TLS)
[2021-02-12 15:21:27,053] ERROR    MQTT: Failed to connect to broker (192.168.1.20:1883): [Errno 111] Connection refused
[2021-02-12 15:21:27,149] WARNING  MQTT: Client no longer connected. Signaling restart to reconnect...
[2021-02-12 15:21:27,161] DEBUG    INFLUXDB: Integration disabled in settings (or due to an error previously)
[2021-02-12 15:21:27,162] ERROR    CLIENTS: Init error: MQTT: Failed to connect to broker

En even later lange reeksen zoals dit:

[2021-02-12 15:24:32,328] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,330] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,348] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m11), 'b'dsmr/reading/electricity_currently_delivered'', ... (5 bytes)
[2021-02-12 15:24:32,350] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,350] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,351] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,353] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,381] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m12), 'b'dsmr/reading/electricity_delivered_2'', ... (7 bytes)
[2021-02-12 15:24:32,383] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,383] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,384] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,386] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,413] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m13), 'b'dsmr/reading/electricity_currently_returned'', ... (5 bytes)
[2021-02-12 15:24:32,414] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,415] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,416] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,418] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,432] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m14), 'b'dsmr/reading/electricity_delivered_2'', ... (7 bytes)
[2021-02-12 15:24:32,433] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,434] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,434] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,436] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,451] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m15), 'b'dsmr/reading/electricity_currently_returned'', ... (5 bytes)
[2021-02-12 15:24:32,452] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,453] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,454] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,456] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,479] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m16), 'b'dsmr/reading/electricity_currently_delivered'', ... (5 bytes)
[2021-02-12 15:24:32,481] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,482] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,483] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,486] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,498] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m17), 'b'dsmr/reading/electricity_delivered_2'', ... (7 bytes)
[2021-02-12 15:24:32,499] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:32,500] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,500] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,502] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,521] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:32,521] WARNING  MQTT: --- Unexpected disconnect, re-connecting...
[2021-02-12 15:24:32,523] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:32,561] WARNING  MQTT: Client no longer connected. Signaling restart to reconnect...
[2021-02-12 15:24:32,562] ERROR    CLIENTS: Run error: MQTT: Client no longer connected
[2021-02-12 15:24:32,584] WARNING  Detected backend restart required, stopping process...
[2021-02-12 15:24:32,585] INFO     dsmr_backend.management.commands.dsmr_backend: [i] Detected StopInfiniteRun exception
[2021-02-12 15:24:32,585] INFO     dsmr_backend.management.commands.dsmr_backend: Exiting on next run...
[2021-02-12 15:24:32,586] DEBUG    dsmr_backend.management.commands.dsmr_backend: Sleeping 10.0s
[2021-02-12 15:24:42,589] DEBUG    CLIENTS: Terminating 1 client(s)
[2021-02-12 15:24:42,589] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending DISCONNECT
[2021-02-12 15:24:42,590] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:42,591] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 0
[2021-02-12 15:24:42,591] DEBUG    dsmr_backend.management.commands.dsmr_backend: Exited
[2021-02-12 15:24:50,368] DEBUG    MQTT: Initializing MQTT client for "192.168.1.20:1883"
[2021-02-12 15:24:50,371] DEBUG    MQTT: Using insecure connection (no TLS)
[2021-02-12 15:24:50,373] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending CONNECT (u0, p0, wr0, wq0, wf0, c1, k60) client_id=b'DSMR-reader'
[2021-02-12 15:24:50,386] DEBUG    INFLUXDB: Integration disabled in settings (or due to an error previously)
[2021-02-12 15:24:50,387] DEBUG    Persistent clients initialized: [<class 'paho.mqtt.client.Client'>]
[2021-02-12 15:24:50,388] DEBUG    dsmr_backend.management.commands.dsmr_backend: Starting infinite command loop...
[2021-02-12 15:24:50,402] DEBUG    SP: 1 backend service(s) ready to run
[2021-02-12 15:24:50,403] DEBUG    SP: Running "Generate consumption data" (dsmr_consumption.services.run)
[2021-02-12 15:24:50,685] DEBUG    Compact: Waiting for newer readings before grouping data...
[2021-02-12 15:24:50,946] DEBUG    SP: Rescheduled "Generate consumption data" to 2021-02-12 15:25:05.685846+01:00 (ETA 0:00:14.739864)
[2021-02-12 15:24:51,818] DEBUG    CLIENTS: Running 1 active client(s)
[2021-02-12 15:24:51,831] INFO     MQTT: Processing 15 message(s)
[2021-02-12 15:24:51,832] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 16 Sending PUBLISH (d0, q0, r1, m1), 'b'dsmr/reading/electricity_currently_returned'', ... (5 bytes)
[2021-02-12 15:24:51,833] DEBUG    MQTT: Paho client: on_log(userdata, level, buf) None 8 failed to receive on socket: [Errno 32] Broken pipe
[2021-02-12 15:24:51,833] DEBUG    MQTT: Paho client: on_disconnect(userdata, rc) None 1
[2021-02-12 15:24:51,834] WARNING  MQTT: --- Unexpected disconnect, re-connecting...

MQTT staat op ingeschakeld, en op admin/dsmr_mqtt/message/ zie ik ook wel uitgaande berichten, maar Home Assistant krijgt niets binnen over MQTT en kan ook niet verbinden.

[8uurg]

Het lijkt erop dat Django in zijn wrapper rond psycopg2 niet goed tijdzones converteert?

>>> with connection.cursor() as cur:
...     cur.execute("SELECT NOW() AT TIME ZONE 'UTC';")
...     cur.fetchall()
...
[(datetime.datetime(2021, 2, 12, 16, 4, 11, 2429),)] # Note: Correct, but no timezone attached.
>>> with connection.cursor() as cur:
...     cur.execute("SET TIMEZONE=0;")
...     cur.execute("SELECT NOW();")
...     cur.fetchall()
...
[(datetime.datetime(2021, 2, 12, 16, 5, 14, 589203, tzinfo=<UTC>),)] # Note: Correct!
>>> with connection.cursor() as cur:
...     cur.execute("SET TIMEZONE=1;")
...     cur.execute("SELECT NOW();")
...     cur.fetchall()
...
[(datetime.datetime(2021, 2, 12, 17, 5, 55, 295760, tzinfo=<UTC>),)] # Note: wrong 
>>> with connection.cursor() as cur:
...     cur.execute("SET TIMEZONE=0;")
...     cur.execute("SHOW TIMEZONE;")
...     cur.fetchall()
...
[('<+00>-00',)]
>>> with connection.cursor() as cur:
...     cur.execute("SET TIMEZONE=1;")
...     cur.execute("SHOW TIMEZONE;")
...     cur.fetchall()
...
[('<+01>-01',)]
>>> with connection.cursor() as cur:
...     cur.execute("SET TIMEZONE='UTC';")
...     cur.execute("SELECT NOW();")
...     cur.fetchall()
...
[(datetime.datetime(2021, 2, 12, 17, 8, 53, 52324, tzinfo=<UTC>),)] # Note: wrong

[dennissiemensma]

@xirixiz wat krijg je terug als je in de dsmr-container dit doet:

./manage.py shell

from django.db import connection
with connection.cursor() as cursor:
    cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
    cursor.fetchall()

# 2x Enter voor resultaat

---

Voorbeeld bij mij:

(InteractiveConsole)
>>> from django.db import connection
>>> with connection.cursor() as cursor:
...     cursor.execute('SELECT timestamp from dsmr_datalogger_dsmrreading order by timestamp desc limit 1')
...     cursor.fetchall()
... 
[(datetime.datetime(2021, 2, 12, 19, 30, 7, tzinfo=<UTC>),)]

[dennissiemensma]

@8uurg welke versie draai je van psycopg2?

pip freeze | grep psycopg2

[8uurg]

@dennissiemensma

bash-5.0# pip freeze | grep psycopg2
psycopg2==2.8.6

[dennissiemensma]

@8uurg oke jammer, die komt overeen. Wat geeft dit op de shell terug? Usernames en wachtwoorden hoef ik uiteraard niet te zien:

from django.conf import settings
from pprint import pprint
pprint(settings.DATABASES, indent=4)

---

>>> from django.conf import settings
>>> from pprint import pprint
>>> pprint(settings.DATABASES, indent=4)
{   'default': {   'ATOMIC_REQUESTS': False,
                   'AUTOCOMMIT': True,
                   'CONN_MAX_AGE': 60,
                   'ENGINE': 'django.db.backends.postgresql',
                   'HOST': 'localhost',
                   'NAME': 'dsmrreader',
                   'OPTIONS': {},
                   'PASSWORD': '********',
                   'PORT': 5432,
                   'TEST': {   'CHARSET': None,
                               'COLLATION': None,
                               'MIGRATE': True,
                               'MIRROR': None,
                               'NAME': None},
                   'TIME_ZONE': None,
                   'USER': '**********'}}
>>> 

[8uurg]

@dennissiemensma Ziet er hetzelfde uit...

>>> from django.conf import settings
rom ppr>>> from pprint import pprint
>>> pprint(settings.DATABASES, indent=4)
{   'default': {   'ATOMIC_REQUESTS': False,
                   'AUTOCOMMIT': True,
                   'CONN_MAX_AGE': 60,
                   'ENGINE': 'django.db.backends.postgresql',
                   'HOST': 'dsmrdb',
                   'NAME': 'dsmrreader',
                   'OPTIONS': {},
                   'PASSWORD': '********',
                   'PORT': 5432,
                   'TEST': {   'CHARSET': None,
                               'COLLATION': None,
                               'MIGRATE': True,
                               'MIRROR': None,
                               'NAME': None},
                   'TIME_ZONE': None,
                   'USER': 'dsmrreader'}}

[dennissiemensma]

En deze?

from django.conf import settings
import os

settings.TIME_ZONE
settings.USE_TZ
os.environ['TZ']

---

>>> from django.conf import settings
>>> import os

>>> settings.TIME_ZONE
'Europe/Amsterdam'

>>> settings.USE_TZ
True

>>> os.environ['TZ']
'Europe/Amsterdam'

[8uurg]

Timezone heb ik zowel op Europe/Amsterdam als nu op UTC gehad.

>>> import os
>>> from django.conf import settings
>>> settings.TIME_ZONE
'UTC'
>>> settings.USE_TZ
True
>>> os.environ['TZ']
'UTC'

[dennissiemensma]

Zaten jullie trouwens hiervoor op een oudere versie van PostgreSQL? Bijvoorbeeld 10 of 11?

[8uurg]

Nope, versie 12, maar eerst op de alpine variant.

En sinds eind januari werkt op die variant datum en tijd niet meer (en crasht daardoor, gok ik, de database):

(op een schone alpine image, zonder enige software)
/ # date
Sun Jan  0 00:100:4174038  1900

Met die update kwam ook wat de database voor mij corrupt heeft gemaakt, en waardoor ik een backup moest terugzetten. Zoals in de docker thread: gebruik maken van de niet alpine versie de oplossing hiervoor geweest.

[Tralapo]

Zaten jullie trouwens hiervoor op een oudere versie van PostgreSQL? Bijvoorbeeld 10 of 11?

Nee, 12 Alpine

Heb trouwens vandaag gemerkt dat als ik mijn Pi reboot, de null errors weer terugkomen en ik eerst jouw fixes weer moet toepassen, @8uurg

[8uurg]

Heb trouwens vandaag gemerkt dat als ik mijn Pi reboot, de null errors weer terugkomen en ik eerst jouw fixes weer moet toepassen, @8uurg

Ik heb de errors ook terug zien komen, voornamelijk nadat ik de tijdzone van Django heb gewijzigd...

[dennissiemensma]

Jullie zouden nog kunnen proberen of jullie dezelfde issues hebben met een nieuwe, lege DB-container op dezelfde versie. Er vanuitgaande dat jullie je huidige container even kunnen stoppen en bewaren (geen idee of dat kan).

Het doel is om te kijken wat er gebeurt met een schone DSMR-reader installatie. Die hoeft dan ook maar een minuut ofzo aan metingen te ontvangen, om te zien of die van hetzelfde last heeft. Naar een paar minuten kunnen jullie vervolgens weer terug naar de huidige.

[8uurg]

Helaas lijkt een lege database geen soelaas te bieden, net zoals met een al gevulde database verwerkt hij geen datapunten van het afgelopen uur: Ook weer met de verkeerde timestamp: het is 21:22, Tijdzone heb ik teruggezet op Europe/Amsterdam.

[dennissiemensma]

Oke, dan ligt het in ieder geval niet aan de backup van destijds.

Ben je wellicht in de gelegenheid om hetzelfde te proberen met een andere versie, zoals Postgres 10, 11 of 13?

[8uurg]

Postgres 13 werkt ook niet:

[8uurg]

Ik kan kijken of een oudere versie van DSMR wel werkt, het heeft immers eerder gewerkt...

[Tralapo]

Jullie zouden nog kunnen proberen of jullie dezelfde issues hebben met een nieuwe, lege DB-container op dezelfde versie. Er vanuitgaande dat jullie je huidige container even kunnen stoppen en bewaren (geen idee of dat kan).

Het doel is om te kijken wat er gebeurt met een schone DSMR-reader installatie. Die hoeft dan ook maar een minuut ofzo aan metingen te ontvangen, om te zien of die van hetzelfde last heeft. Naar een paar minuten kunnen jullie vervolgens weer terug naar de huidige.

Ik ben nog steeds met deze opdracht bezig want mijn Pi is altijd extreem traag bij het bouwen van containers, maar verwacht dat het resultaat dan wel hetzelfde zal zijn als @8uurg

[dennissiemensma]

Zaten jullie eerder op een oudere versie van DSMR-reader en zijn jullie tegelijkertijd, met de wisseling van 12 Alpine naar 12, overgegaan naar DSMR-reader v4.11? Of waren jullie al eerder op DSMR-reader v4.11?

[8uurg]

Ik zat op een versie van rond begin januari, en voerde een update uit, wat zowel voor DMSR als de DB een update uitvoerde.

[Tralapo]

Ik heb zaterdag al mijn containers (en dus ook DSMR) geüpdate, dat doe ik eens per maand.

Daarna liep alles vast en deden DSMR én de DB niets anders dan constant rebooten tot de Pi crashte. Toen heb ik op aanraden van @xirixiz de postgres-versie gewijzigd naar niet-alpine en een backup teruggezet (want alles was kapot).

Daarna bleef dit probleem over.

De backup die ik heb teruggezet is één van de daily backups die DSMR zelf maakt. Die was dus gemaakt door een oudere versie van DSMR én met postgres-12-alpine.

Ik weet niet welke versie van DSMR ik precies draaide.

[dennissiemensma]

Oke helder. Laat maar weten of bijvoorbeeld v4.10 het beter doet.

De wijzigingen inhoudelijk zijn vrij gering: https://github.com/dsmrreader/dsmr-reader/compare/v4.10.0...v4.11.0 Ook qua dependencies: v4.10.0...v4.11.0 deps

[8uurg]

4.11 ❌ 4.10 ❌ 4.9 ❌ -- maar processing staat niet in het adminpaneel... 4.8 ❌ , en dit is de oudste versie die ik zelf mogelijk heb gebruikt...

Dus wellicht is het probleem er al een tijdje, en heb ik het nooit opgemerkt voordat het fout ging.

[Tralapo]

Ik heb de DB-container verwijderd, de data weggehaald en een nieuwe DB-container gemaakt, maar het enige wat ik dan zie is een lege DSMR interface met deze melding:

Geen gegevens gevonden. Zorg ervoor dat het dsmr_datalogger-proces draait of dat je gegevens aanlevert via die API. Daarnaast hoort het dsmr_backend-proces eveneens te draaien.

[dennissiemensma]

Ik weet dan eerlijk gezegd niet meer waar het aan kan liggen. Het moet iets heel subtiels zijn, want ik heb het idee dat het niet bij iedereen speelt. En alleen bij Docker. Anders had ik hier al wel meer meldingen verwacht. Of indirect via xirixiz.

Plus dat ook nog een derde persoon in #1288 last van exact hetzelfde heeft, ook Docker, ook null-waardes, ook tijdsverschil.

[8uurg]

Ik denk dat de null waardes komen van de metingen van een ~1 uur geleden die bij afsluiten verwerkt werden, het aantal dat wordt verwijderd is ongeveer gelijk die hoeveelheid.

Verder: Er is bij mij in ieder geval een grote lijn te trekken langs alle problemen: het heeft met tijd (en tijdzones) te maken 😕

• Database met alpine corrupt omdat tijd stopt met werken in nieuwe db container
  • Overgestapt naar niet alpine image: alternative database image, wellicht met andere tijdzonedata?
• Django voegt 1 uur toe bij converteren data met timestamp... Terwijl dit met psycopg2 + pytz (via utc.normalize) wel goed gaat.

Ik ben het met je eens dat het probleem hier wel eens heel subtiel kan zijn...

[Tralapo]

Ik heb de database gewijzigd naar postgres:12.3-alpine die volgens de site circa 8 maanden oud is. Link

DSMR start goed op, alle tijden op admin/dsmr_datalogger/dsmrreading/ lijken te kloppen en hij is nu bezig met het verwerken van 6000 telegrammen.... even afwachten.

[8uurg]

Als ik dezelfde database image gebruik als @Tralapo, dan is dit ook bij mij opgelost. Blijkbaar brengt de standaard image (niet alpine) ook problemen met zich mee...

[dennissiemensma]

Echt? Dat lost het op?

[Tralapo]

Hij is nu klaar met het verwerken van alle telegrammen en inderdaad, alles lijkt opgelost. Morgen maar eens per versie postgres ophogen om te checken vanaf welke versie het precies fout gaat, nu geen zin meer in ;)

[dennissiemensma]

@pcdiks probeer ook 12.3-alpine eens: https://github.com/dsmrreader/dsmr-reader/issues/1282#issuecomment-778457502

[8uurg]

Blijkbaar wel. Zo te zien is @xirixiz zijn container ook op alpine gebouwd: python:3-alpine, dus wellicht dat het mengen van de twee voor problemen zorgt. Ik weet namelijk wel dat alpine ietswat apart is met zijn eigen c library en timezones.

Verder ben ik bang dat verdere updates van de container dus zelf weer een datumprobleem meebrengen zoals bij de database...

EDIT: De upstream versie van python:3-alpine is inderdaad ook kapot, dus wellicht wachten met updaten:

Unable to find image 'python:3-alpine' locally
3-alpine: Pulling from library/python
9b1db703a337: Already exists
1d00033007f6: Pull complete
23a53167f4d4: Pull complete
cfecd0db6953: Pull complete
8f7be45c57c8: Pull complete
Digest: sha256:db35c8d2e810559d90af0a126dac55cf93601202061d3f61f94ac3c460d4a211
Status: Downloaded newer image for python:3-alpine
Fatal Python error: init_interp_main: can't initialize time
Python runtime state: core initialized
PermissionError: [Errno 1] Operation not permitted

Current thread 0xb6fa8390 (most recent call first):
<no Python frame>

Ik denk dat deze issue bij Alpine Linux wellicht relevant is: https://gitlab.alpinelinux.org/alpine/aports/-/issues/12346, verder is libseccomp out of date op Raspbian stable (https://wiki.alpinelinux.org/wiki/Release_Notes_for_Alpine_3.13.0#time64_requirements) wat ook voor problemen omtrent Alpine Linux en tijd kan zorgen...

@dennissiemensma Het zou best kunnen dat de issue met Django dezelfde oorzaak heeft als bij Ruby hier: https://stackoverflow.com/questions/64581249/rails-activesupport-time-and-timezone-error-on-alpine-linux

[pcdiks]

Ik heb in mijn docker-compose nu 12.3-alpine staan en ik heb geen last meer van de achterblijvende berichten en het uur tijdsverschil. Dit tijdsverschil werkt helemaal door in het systeem zelfs tot aan de upload naar pvoutput. Daar zat ik toevallig gisteren en vanmorgen naar te kijken en het viel me op dat in de grafieken ik al info had voor een uur vooruit. Dat is nu vast ook opgelost.

Ik heb nu alleen nog dat ik 5 dagstatistieken achter loop. Lost dat vanzelf op of moet ik daar nog wat voor doen?

[xirixiz]

Ik gebruik zelf voor de db geen Alpine meer, al een tijd niet meer, maar zal de docker-compose daar ook op aanpassen. Wellicht kan ik de base image van dsmr ook aanpassen, al wordt de image dan stukken groter....dat is dan weer het nadeel.

Ik zal het eens overdenken, maar volgens mij is het grootste probleem de Alpine postgres image. Dit weekend zal ik eens een DSMR image maken gebaseerd op debian-slim, ik lees dat het eigenlijk ook beter is om te gebruiken icm Python