Docker: API error: HTTP 500 - Failed to parse telegram

[CptChaos]

Description

Recently, I noticed my DSMR installation wasn't working anymore. I switched to Docker and must've removed everything I had before as well. All in all: I needed to create a new installation. A lot has changed, so after some trying around, I came to the point I had my installation running: two instances of DSMR. One on my Pi, as api_client, the other as api_server. For both instances, I use Docker (xirixiz's container).

After enabling the API on the server, and setting the API key to the api_client and (to be sure) a container restart, the api_client is sending the telegrams to api_server. But upon doing that, it receives an HTTP 500 every time a telegram is posted. I don't know what I am doing wrong, and I am hoping you guys can help me out.

For both DSMR instances, I use docker-compose. For the api_server the Docker-compose file is as follows:

version: '3'

services:
  dsmrdb:
    # When using Postgres, release 13.x is supported only
    # due to the limited availability of client packages, especially for arm32v7
    image: postgres:14-alpine
    container_name: dsmrdb
    restart: unless-stopped
    volumes:
      - ./dsmrdb/database:/var/lib/postgresql/data
    environment:
      - TZ=Europe/Amsterdam
      - PG_TZ=Europe/Amsterdam
      - POSTGRES_USER=dsmrreader
      - POSTGRES_PASSWORD=dsmrreader
      - POSTGRES_DB=dsmrreader
    healthcheck:
      # postgres is the default user, please update with
      # the DJANGO_DATABASE_USER used for dsmr-reader-docker
      # default for DSMR Reader is dsmrreader
      test: [ "CMD-SHELL", "pg_isready -U dsmrreader" ]
      interval: 10s
      timeout: 5s
      retries: 10

  dsmr:
    image: xirixiz/dsmr-reader-docker:latest
    depends_on:
      - dsmrdb
    container_name: dsmr
    links:
      - dsmrdb
    cap_add:
      - NET_ADMIN
    restart: unless-stopped
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - ./dsmr/app/backups:/app/backups
    environment:
      - TZ=Europe/Amsterdam
      - DJANGO_TIME_ZONE=Europe/Amsterdam
      - VIRTUAL_HOST=localhost
      - DSMRREADER_OPERATION_MODE=api_server
    ports:
      - 7777:80
    # healthcheck:
    #   disable: true
    healthcheck:
      test:
        [
          "CMD",
          "curl",
          "-Lsf",
          "http://127.0.0.1/about",
          "-o",
          "/dev/null",
          "-w",
          "HTTP_%{http_code}"
        ]
      interval: 10s
      timeout: 5s
      retries: 10

for the api_client instance, the docker-compose.yml file is looking like this:

services:
  dsmr:
    image: xirixiz/dsmr-reader-docker:latest
    container_name: dsmr
    restart: unless-stopped
    cap_add:
      - NET_ADMIN
    volumes:
      - /etc/localtime:/etc/localtime:ro
    environment:
      - TZ=Europe/Amsterdam
      - DJANGO_TIME_ZONE=Europe/Amsterdam
      - DSMRREADER_REMOTE_DATALOGGER_API_KEYS=** REDACTED API KEY HERE **
      - DSMRREADER_REMOTE_DATALOGGER_API_HOSTS=http://192.168.0.122:7777
      - DSMRREADER_OPERATION_MODE=api_client
      - DSMRREADER_REMOTE_DATALOGGER_SLEEP=5
      - DSMRREADER_REMOTE_DATALOGGER_DEBUG_LOGGING=false
      - DSMRREADER_LOGLEVEL=WARNING
      - DSMRREADER_REMOTE_DATALOGGER_INPUT_METHOD=serial
      - DSMRREADER_REMOTE_DATALOGGER_SERIAL_PORT=/dev/ttyUSB0
      - DSMRREADER_REMOTE_DATALOGGER_SERIAL_BAUDRATE=9600
      - DSMRREADER_REMOTE_DATALOGGER_SERIAL_BYTESIZE=7
      - DSMRREADER_REMOTE_DATALOGGER_SERIAL_PARITY=E
    devices:
      - /dev/ttyUSB0:/dev/ttyUSB0

It maybe has something to do with the database. When I change the admin password and restart the api_server instance, the password is back to default too. Maybe I am missing something, but I am not sure, as the Postgres folder structure is created in the volume mount.

DSMR-reader version

5.10.2

DSMR-reader platform

Docker (Xirixiz)

Debug info dump

-READER
    App / Python / Database                                                    v5.10.2 / v3.11.1 / postgresql
    BE sleep / DL sleep / Retention / Override                                     1.0s / 5.0s / 672h / False
    Latest telegram version read / Parser settings                                               "None" / "4"

DATA
    Telegrams total (est.)                                                                                 -1
    Consumption records electricity / gas (est.)                                                      -1 / -1

UNRESOLVED ISSUES
    Geen dagstatistieken gevonden                                                                          nu
    Nog nooit een meting ontvangen                                                                         nu

[dennissiemensma]

Unfortunately this seems like a Docker issue. You should be able to check the container logs for more details. One thing I already see is the comment "When using Postgres, release 13.x is supported only" and you're using v14. You might want to try using v13 instead, as it could be the cause of the issues. Fortunately docker makes it really easy to switch container versions, but you'll lose any data stored so far (if any).

[CptChaos]

Unfortunately this seems like a Docker issue. You should be able to check the container logs for more details. One thing I already see is the comment "When using Postgres, release 13.x is supported only" and you're using v14. You might want to try using v13 instead, as it could be the cause of the issues. Fortunately docker makes it really easy to switch container versions, but you'll lose any data stored so far (if any).

Hmmm, that is interesting. That would mean that the example file from Xirixiz that I used, is using the wrong version of Postgres by default as well. I will try if that works, thanks for the tip!

EDIT: Switching to PostgreSQL 13 didn't resolve the issue: dsmr | [2023-01-31 19:34:55.966985] API error: HTTP 500 - Failed to parse telegram Is still what I get on the api_client instance of DSMR. With debugging enabled, it gives the HTTP 500 bad gateway page from Nginx

EDIT 2: On api_server this is what I get after a POST of data: dsmr | 192.168.0.4 - - [31/Jan/2023:19:36:46 +0100] "POST /api/v1/datalogger/dsmrreading HTTP/1.1" 500 24 "-" "python-requests/2.28.1" "-"

[dennissiemensma]

@Xirixiz weet jij of PostgreSQL 14 inmiddels al goed ondersteund wordt? Of geldt de comment in je sample nog steeds en staat die sample onbedoeld op 14? Los van of dat überhaupt met het huidige issue te maken heeft uiteraard. 😁

[dennissiemensma]

@cptchaos any clue what telegram is sent to the server? Unfortunately the error is quite generic.

[CptChaos]

The only clue I have is that it sends a telegram with both my electric and gas usages etc, and info like when the usage is in "daluren". As you've probably seen by the settings from api_client, I have an older "slimme meter" and have to use different settings in order to get a reading out of it. These settings I managed to retrieve from the settings I had before, so I know those settings work and give a readable result, it worked in the past.

I wish I knew Python a lot better, would make debugging things easier for me :P

[xirixiz]

@xirixiz weet jij of PostgreSQL 14 inmiddels al goed ondersteund wordt? Of geldt de comment in je sample nog steeds en staat die sample onbedoeld op 14? Los van of dat überhaupt met het huidige issue te maken heeft uiteraard. 😁

Hi, I`m using PG14 for quiet some time now, and it's working fine. I guess the line with the note about PG13 is there because a docker-compose file from the past was used. @CptChaos better to just remove it....

Looking at the issue it could be related that data is incorrectly formed that is send to the DSMR Reader (or api server in your case). It could be the serial values are incorrect. Maybe you can set DSMRREADER_LOGLEVEL to debug? @dennissiemensma do you have some sort of curl command with dummy data to validate the api_server is accepting posted data (telegrams)?

What is connected to you RPI, is it a USB P1 cable? Can you validate that data is being retrieved on /dev/ttyUSB0? Is /dev/ttyUSB0 really the device, or could it be that it's mapped as a different device, /dev/ttyUSB1 for example?

 cu -l /dev/ttyUSB0 -s 115200 --parity=none

[CptChaos]

@xirixiz I just used the sample mentioned on this page: https://github.com/xirixiz/dsmr-reader-docker.

Where do you want me to put the loglevel to debug? On the api_client or on api_server, or on both?

[xirixiz]

Both.... I see now.... updated the example. Thanks 😄

[xirixiz]

Je kan het ook even met een Python scriptje testen wanneer cu niet beschikbaar is als package. Je kan dan een beetje met de seriele settings spelen wanneer je geen data kan lezen, mogelijk zijn de default waarden het issue. Let op dat de api_client Docker container dan wel gestopt moet zijn, zowel met cu of met het onderstaande script.

Script:

#!/usr/bin/env python
import time
import serial

ser = serial.Serial(
        port='/dev/ttyUSB0',
        baudrate = 9600,
        parity=serial.PARITY_EVEN,
        stopbits=serial.STOPBITS_ONE,
        bytesize=serial.SEVENBITS,
        timeout=1
)

while 1:
        x=ser.readline()
        print (x)

Output moet ongeveer zo zijn iedere paar seconden:

xirixiz@NAS /volume1/onedrive/smarthome                                                                                                                                                                                        [7/341]-> python3 test.py
b'\x00\n'
b''
b'/ISk5\\2MT382-1003\r\n'
b'\r\n'
b'0-0:96.1.1(5A424244303035313431353038393133)\r\n'
b'1-0:1.8.1(19267.903*kWh)\r\n'
b'1-0:1.8.2(16501.152*kWh)\r\n'
b'1-0:2.8.1(00000.001*kWh)\r\n'
b'1-0:2.8.2(00000.004*kWh)\r\n'
b'0-0:96.14.0(0001)\r\n'
b'1-0:1.7.0(0000.44*kW)\r\n'
b'1-0:2.7.0(0000.00*kW)\r\n'
b'0-0:17.0.0(0999.00*kW)\r\n'
b'0-0:96.3.10(1)\r\n'
b'0-0:96.13.1()\r\n'
b'0-0:96.13.0()\r\n'
b'0-1:24.1.0(3)\r\n'
b'0-1:96.1.0(3238313031353431303038353934333132)\r\n'
b'0-1:24.3.0(230131210000)(00)(60)(1)(0-1:24.2.1)(m3)\r\n'
b'(15537.010)\r\n'
b'0-1:24.4.0(1)\r\n'
b'!\r\n'

Een andere optie zou kunnen zijn deze waarden gewoon te testen op de api_client:

DSMRREADER_REMOTE_DATALOGGER_SERIAL_BAUDRATE=115200
DSMRREADER_REMOTE_DATALOGGER_SERIAL_BYTESIZE=8
DSMRREADER_REMOTE_DATALOGGER_SERIAL_PARITY=N

Of bijpassende Python code voor 115200:

#!/usr/bin/env python
import time
import serial

ser = serial.Serial(
        port='/dev/ttyUSB0',
        baudrate = 115200,
        parity=serial.PARITY_NONE,
        stopbits=serial.STOPBITS_ONE,
        bytesize=serial.EIGHTBITS,
        timeout=1
)

while 1:
        x=ser.readline()
        print (x)

Hoe dan ook moet er bij de test leesbare output tussen zitten zoals in het bovenstaande voorbeeld. Zoiets als dit is niet goed:

b''
b''
b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\

Meer info: https://pyserial.readthedocs.io/en/latest/pyserial_api.html

[dennissiemensma]

@CptChaos geeft de log van de container met de api_client ook geen telegram-info bij DSMRREADER_LOGLEVEL=DEBUG? Zoals Bram al aangeeft is dat loglevel op beide aanzetten vermoedelijk het meeste praktische.

[CptChaos]

Met cu -l /dev/ttyUSB0 -s 9600 --parity=none krijg ik de melding dat 'de lijn' in gebruik is en het Python script valt over module serial:

pi@raspberrypi:/home/pi/docker# python test.py
Traceback (most recent call last):
  File "/home/pi/docker/test.py", line 3, in <module>
    import serial
ModuleNotFoundError: No module named 'serial'

[xirixiz]

Ja klopt, je moet de container stoppen voordat je cu gebruikt of het Python script. Er mag maar 1 proces gelijktijdig het device uitlezen. Python werkt met libraries/modules. Je kan het package eenvoudig installeren met pip3 install serial --user of pip, al moet het package pip dan ook geinstalleerd zijn :). Aangezien cu al geinstalleerd is en werkt zou ik dat gebruiken.

[dennissiemensma]

Als je cu gebruikt (of iets anders er naast) zul je wel even DSMR-reader moeten stoppen. De seriele poort kan maar door 1 applicatie tegelijkertijd uitgelezen worden.

[CptChaos]

Ah ja, dat was ik vergeten te zeggen: DSMR draaide niet.

[xirixiz]

Oke, dan lijkt het er dus op dat er met de poort als iets niet goed zit. Wanneer er geen enkel proces /dev/ttyUSB0 gebruikt, dan moet je hoe dan ook het device uit kunnen lezen. Je kan even kijken met lsof /dev/ttyUSB0

[CptChaos]

Met lsof /dev/ttyUSB0 krijg ik geen resultaten terug. Ik gebruikte de nieuwste versie van het package, want heb net lsof moeten installeren op mijn Pi.

De output van het cu -l /dev/ttyUSB0 -s 9600 --parity=none commando is het volgende:

cu: open (/dev/ttyUSB0): Permission denied
cu: /dev/ttyUSB0: Line in use

Ook wanneer ik met sudo gebruik

[xirixiz]

Kan je cu met sudo uitvoeren.... of sudo chmod 777 /dev/ttyUSB0 uitvoeren.

...oke, doe je al met sudo. Kan je de rechten aanpassen?

Stap 1 is er iig achter komen dat de seriele verbinding naar behoren werkt, daarna komt de api_client, daarna de api_server.... als de problemen dan nog spelen.

[CptChaos]

Bingo, het was blijkbaar een rechten dingetje. Mijn telegrammen zien er als volgt uit:

/XMX5XMXABCE100085144

0-0:96.1.1(31333836353130372020202020202020)
1-0:1.8.1(13987.433*kWh)
1-0:1.8.2(12843.754*kWh)
1-0:2.8.1(00000.000*kWh)
1-0:2.8.2(00000.000*kWh)
0-0:96.14.0(0002)
1-0:1.7.0(0000.45*kW)
1-0:2.7.0(0000.00*kW)
0-0:96.13.1()
0-0:96.13.0()
0-1:96.1.0(3238303131303038333037313834393133)
0-1:24.1.0(03)
0-1:24.3.0(230131220000)(00)(60)(1)(0-1:24.2.0)(m3)
(05370.189)

Dit lijkt mij verder gewoon prima.

[xirixiz]

Rechten zou dan ook het issue kunnen zijn geweest in de docker container.... ik zou de boel eens herstarten nu :)

[CptChaos]

Wel gek, want ik heb niets aangepast en had hiervoor ook gewoon DSMR draaien, met een iets andere setup want oudere versie.

EDIT: Ik heb net de api_client gestart, maar die krijgt nog steeds een HTTP 500 error. Dit soort fouten geven meestal ook server errors aan. Dus zou het ook wel vreemd hebben gevonden als dit zou werken.

EDIT2: Met de debug output heb ik wel wat meer informatie nu:

dsmr      | 2023-01-31 22:44:42,071 WARNING  datalogger   telegram_to_reading              90 | Rejected telegram: Failed to perform CRC validation because the telegram is incomplete. The checksum and/or content values are missing.

[xirixiz]

Inhoudelijk weet ik verder niet precies hoe het werkt, maar misschien dat @dennissiemensma meer kan met deze melding. Ik denk dat je hierover ook wel iets kan vinden tussen de closed issues.

[CptChaos]

Voor de volledigheid de gehele entry in de log:

dsmr      | 2023-01-31 22:44:42,070 DEBUG    datalogger   telegram_to_reading              81 | Received telegram:
dsmr      | /XMX5XMXABCE100085144
dsmr      |
dsmr      | 0-0:96.1.1(31333836353130372020202020202020)
dsmr      | 1-0:1.8.1(13987.433*kWh)
dsmr      | 1-0:1.8.2(12843.787*kWh)
dsmr      | 1-0:2.8.1(00000.000*kWh)
dsmr      | 1-0:2.8.2(00000.000*kWh)
dsmr      | 0-0:96.14.0(0002)
dsmr      | 1-0:1.7.0(0000.44*kW)
dsmr      | 1-0:2.7.0(0000.00*kW)
dsmr      | 0-0:96.13.1()
dsmr      | 0-0:96.13.0()
dsmr      | 0-1:96.1.0(3238303131303038333037313834393133)
dsmr      | 0-1:24.1.0(03)
dsmr      | 0-1:24.3.0(230131220000)(00)(60)(1)(0-1:24.2.0)(m3)
dsmr      | (05370.189)
dsmr      | !
dsmr      | 2023-01-31 22:44:42,071 WARNING  datalogger   telegram_to_reading              90 | Rejected telegram: Failed to perform CRC validation because the telegram is incomplete. The checksum and/or content values are missing.
dsmr      | 192.168.0.4 - - [31/Jan/2023:22:44:42 +0100] "POST /api/v1/datalogger/dsmrreading HTTP/1.1" 500 24 "-" "python-requests/2.28.1" "-"

@xirixiz Nu moet ik ook wel zeggen dat ik het wat raar vind dat ik volgens mij wel een gevulde database heb, maar wanneer ik de container van api_server herstart, wel weer de default inloggegevens heb. Worden die niet opgeslagen in de database?

[xirixiz]

Die 500 error kan wel kloppen, de server ontvangt een invalid object, wat ook matcht met die crc error. Het wachtwoord wordt inderdaad niet opgeslagen, die moet je dan als vars zetten, dat kan je wel in de README vinden en staat iig los van dit issue.

Even wachten wat Dennis kan vertellen over die CRC error. Ik denk dat dit eenvoudig te verhelpen is.

[CptChaos]

Thanks, @xirixiz dan ga ik dat alvast even fixen! :) Thanks voor alle hulp zover!

[xirixiz]

Graag gedaan en succes verder!

[dennissiemensma]

@CptChaos ik denk dat je aan de API-server zijde de Datalogger instellingen binnen de DSMR-reader admin op Netherlands - DSMR version 2/3 moet zetten.

Je telegram lijkt aardig overeen te komen met die legacy DSMR: https://github.com/dsmrreader/dsmr-reader/blob/v5/dsmr_datalogger/tests/datalogger/test_iskra.py#L21

Rejected telegram: Failed to perform CRC validation because the telegram is incomplete. The checksum and/or content values are missing

[CptChaos]

@dennissiemensma Dat was het inderdaad, het werkt nu! Bedankt allemaal!