Async Serial / Keep socket open (DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT)

RoboMagus commented 1 year ago

Feature

Heb mijn configuratie gemigreerd naar een draadloze setup d.m.v. ESP8266 met een EspHome Telnet server waar dsmr-reader de telegrams vanaf leest. Hierbij viel het me op dat deze verbinding steeds wegvalt en opnieuw wordt opgezet wat voor extra boekhouding zorgt bij het ESP8266 chipje.

Na wat browsen in deze repo is het by design dat voor iedere telegram de verbinding opnieuw wordt gemaakt en afgebroken, waarbij in de tussentijd actief gewacht wordt. Dit verklaart ook het relatief hoge CPU gebruik van dsmr-reader t.o.v. andere meer veel eisende services die ik op mijn RPi4 draai. Hierop vondt ik issue #774, waarin de mogelijkheid van async processing genoemd is.

Staat deze verbetering nog op de roadmap? En bestaat er wellicht een goede reden die ik niet voorzie voor het steeds opnieuw opzetten van de seriele verbinding / telnet socket?

Thanks!

dennissiemensma commented 1 year ago

Bedankt voor je melding. Als ik het me goed herinner was dit gedrag vroeger inderdaad zo, maar zou de verbinding nu juist behouden moeten worden door DSMR-reader. Je kunt debug logging inschakelen en kijken of de datalogger-logs van DSMR-reader aangeven dat en waarom de verbinding verbroken wordt. Het kan ook in de onderliggende pyserial library zitten, maar dan is het me niet eerder opgevallen.

dennissiemensma commented 1 year ago

Ja volgens mij hebt ik het hier toen herschreven en gelijkgetrokken. https://github.com/dsmrreader/dsmr-reader/issues/774#issuecomment-584380157

dennissiemensma commented 1 year ago

Het kan zijn dat het gedrag van inet4 connecties, zoals socat, anders is dan de seriële variant uit dat issue. Maar dat is dan nooit opgevallen.

dennissiemensma commented 1 year ago

Ik heb even geprobeerd met ser2net en socket://localhost:4000. Ik zie alleen onderstaande melding als ik de datalogger herstart:

2023-05-31 21:34:21,111 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-05-31 21:34:21.111208] Opening connection "socket://localhost:4000" using options: {}

Dat zeggende hebben is dat niet perse wat er onderwater gebeurt. Al zie ik in pyserial's socket class ook geen bijzonderheden.

Je kunt het beste even DSMR-reader tijdelijk met DSMRREADER_LOGLEVEL=DEBUG draaien en kijken in de datalogger log. Wellicht staan er connectiefouten.

dennissiemensma commented 1 year ago

Je kunt ook nog de datalogger stoppen en even kort handmatig draaien met strace, zodat je wellicht "iets" meer ziet. Maar dat is wel erg low-level.

sudo supervisorctl stop dsmr_datalogger

sudo su - dsmr
strace -f -v -s 1024 ./manage.py dsmr_datalogger

Alleen komt er zoveel data dan langs (helemaal als je elke seconde een telegram krijgt), dat het ook weer teveel kan zijn.

RoboMagus commented 1 year ago

Thanks voor je snelle reactie. Ik ging er vanuit dat het wellicht een object lifetime issue was van het serial_handle object in de read_telegram functie. Maar geen idee hoe dit vanuit de Serial library afgehandeld wordt.

Ongeveer iedere 20 seconden wordt de verbinding opnieuw opgezet in mijn situatie. Hieronder de logs:

docker logs -n 100 -f dsmr-reader 2>&1 | grep INFO

2023-06-03 16:58:13,396 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:58:13.396870] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 16:58:33,188 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:58:33.188450] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 16:58:53,019 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:58:53.019913] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 16:59:12,472 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:59:12.472248] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 16:59:32,699 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:59:32.699682] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 16:59:52,347 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 16:59:52.347118] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:00:12,299 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:00:12.299719] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:00:31,686 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:00:31.685877] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:00:51,652 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:00:51.652762] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:01:11,565 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:01:11.565079] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:01:30,978 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:01:30.978878] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:01:51,137 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:01:51.137818] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:02:10,973 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:02:10.973211] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:02:30,637 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:02:30.637785] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:02:50,613 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:02:50.613856] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:03:09,994 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:03:09.994502] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:03:29,482 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:03:29.482363] Opening connection "socket://192.168.1.110:23" using options: {}
2023-06-03 17:03:49,812 INFO     dsmr_datalogger_api_client read_telegram                    31 | [2023-06-03 17:03:49.812788] Opening connection "socket://192.168.1.110:23" using options: {}

dennissiemensma commented 1 year ago

In theorie zou de yield alles op de achtergrond moeten houden tot de volgende aanroep. Of DSMR-reader moet dat expliciet niet doen bij het aanroepen van die functie, maar dan zou het überhaupt al niet moeten werken (bij mij). https://github.com/dsmrreader/dsmr-reader/blob/a11ad666e9823ec532992f9ee66a93ea2bdaf321/dsmr_datalogger/scripts/dsmr_datalogger_api_client.py#L76. Dan wordt het denk ik een kwestie van debuggen om te kijken waarom die loop stopt.

RoboMagus commented 1 year ago

Heb een kort testje gedraaid dmv onderstaand scriptje. Ook hierbij valt steeds de verbinding weg met de telnet server.

import socket, string, sys, serial

while True:
  serial_handle = serial.serial_for_url(url="socket://192.168.1.110:23", timeout=10)
  serial_handle.read_until(b'\r\n\r\n')

RoboMagus commented 1 year ago

Found the culprit!

Deze regel sluit de verbinding steeds. De waarde van self.sleep_time is ingesteld op 6 seconden op basis van het volgende advies:

Het aantal seconden dat de applicatie wacht na het inlezen van gegevens via de datalogger (API en remote datalogger uitgezonderd). De aanbevolen waarde is 5 seconden of hoger en heeft geen invloed op de dagtotalen!

Omdat settings.DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT vast staat op 1.0s wordt de verbinding dus steeds gesloten.

Ik heb geen mogelijkheid gevonden om DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT via de settings te wijzigen. Is dit via Env. variables mogelijk?

dennissiemensma commented 1 year ago

Goeie, die was ik vergeten. Dat verklaart het wel. Draai je DSMR-reader via een native installatie? Want dan is het nog wel handmatig in te stellen.

RoboMagus commented 1 year ago

Nope, heb het draaien via Docker.

Maar ik begrijp dat dit dus niet een eenvoudige aanpassing is? Wat is de reden voor zo'n korte tijd voor DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT? Heeft dit te maken met een keep-alive die voor sommige sockets anders overschreden wordt?

dennissiemensma commented 1 year ago

Ik kan het herleiden naar:

1114
1107

Je bent de eerste die er andersom tegenaan loopt.

Een mogelijke workaround is dat je lokaal dsmrreader/config/production.py aanpast door daar onderaan op een nieuwe regel DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT = 10 te zetten en het datalogger-proces te herstarten.

Dat zou die dat moeten gebruiken. Alleen is dit wellicht wat lastiger via Docker installatie dan een native.

dennissiemensma commented 1 year ago

Ik zal in een volgende release DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT als ongedocumenteerde env var ontsluiten.

Ongedocumenteerd omdat het behoorlijk low-level is en eigenlijk de fix in #1107 tegenwerkt. De datalogger is bedoeld als generieke oplossing voor vele gebruikers en niet als super-optimaliseerd script. Echter, gezien de wijziging en impact beperkt is, kan ik hier wel mee leven.

dsmrreader / dsmr-reader

Async Serial / Keep socket open (DSMRREADER_DATALOGGER_MIN_SLEEP_FOR_RECONNECT) #1861

Feature

1114

1107