🙋 ineens een 504 timeout - dsmr processen draaien nog wel

[mkruiver]

Description

Ik heb ineens een 504 gateway timeout op nginx.

Alle processen draaien wel, en een deploy.sh werkt ook gewoon. De backend heeft wel errors in de log.
What happened?

[2021-11-20 18:32:50 +0100] [1609] [INFO] Booting worker with pid: 1609
[2021-11-20 18:34:24 +0100] [669] [CRITICAL] WORKER TIMEOUT (pid:1609)
[2021-11-20 18:34:25 +0100] [669] [WARNING] Worker with pid 1609 was terminated due to signal 9
[2021-11-20 18:34:25 +0100] [1624] [INFO] Booting worker with pid: 1624
[2021-11-20 18:55:52 +0100] [669] [INFO] Handling signal: term
[2021-11-20 18:55:52 +0100] [1624] [INFO] Worker exiting (pid: 1624)
[2021-11-20 18:55:53 +0100] [669] [INFO] Shutting down: Master
[2021-11-20 18:56:11 +0100] [658] [INFO] Starting gunicorn 20.1.0
[2021-11-20 18:56:11 +0100] [658] [INFO] Listening at: unix:/var/tmp/gunicorn--dsmr_webinterface.socket (658)
[2021-11-20 18:56:11 +0100] [658] [INFO] Using worker: sync
[2021-11-20 18:56:11 +0100] [873] [INFO] Booting worker with pid: 873

Backend log zegt dit:

Current logging level  to "ERROR". More information can be found here: https://dsmr-reader.readthedocs.io/en/latest/how-to/troubleshooting/enabling-debug-logging.html
2021-11-20 18:55:47,816 ERROR    schedule     execute_scheduled_processes      41 | (OperationalError) dsmr_consumption.services.run errored: terminating connection due to administrator command
SSL connection has been closed unexpectedly

2021-11-20 18:55:48,619 ERROR    mixins       run_once                        103 | dsmr_backend.management.commands.dsmr_backend: [!] Exception raised. Traceback (most recent call last):
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
psycopg2.OperationalError: terminating connection due to administrator command
SSL connection has been closed unexpectedly


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_backend/services/schedule.py", line 35, in execute_scheduled_processes
    current.execute()
  File "/home/dsmr/dsmr-reader/dsmr_backend/models/schedule.py", line 60, in execute
    return service(self)
  File "/home/dsmr/dsmr-reader/dsmr_consumption/services.py", line 32, in run
    for current_reading in DsmrReading.objects.unprocessed()[0:settings.DSMRREADER_COMPACT_MAX]:
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/query.py", line 287, in __iter__
    self._fetch_all()
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/query.py", line 1308, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/query.py", line 53, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch, chunk_size=self.chunk_size)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1156, in execute_sql
    cursor.execute(sql, params)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/utils.py", line 66, in execute
    return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
    return executor(sql, params, many, context)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/utils.py", line 84, in _execute
    return self.cursor.execute(sql, params)
django.db.utils.OperationalError: terminating connection due to administrator command
SSL connection has been closed unexpectedly


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/base/base.py", line 237, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/utils/asyncio.py", line 26, in inner
    return func(*args, **kwargs)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/postgresql/base.py", line 236, in create_cursor
    cursor = self.connection.cursor()
psycopg2.InterfaceError: connection already closed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/dsmr/dsmr-reader/dsmr_backend/mixins.py", line 92, in run_once
    self.run(data=self.data, **options)
  File "/home/dsmr/dsmr-reader/dsmr_backend/management/commands/dsmr_backend.py", line 33, in run
    dsmr_backend.services.schedule.execute_scheduled_processes()
  File "/home/dsmr/dsmr-reader/dsmr_backend/services/schedule.py", line 45, in execute_scheduled_processes
    current.delay(seconds=30)
  File "/home/dsmr/dsmr-reader/dsmr_backend/models/schedule.py", line 67, in delay
    self.reschedule(planned_at=timezone.now() + timezone.timedelta(**delta))
  File "/home/dsmr/dsmr-reader/dsmr_backend/models/schedule.py", line 74, in reschedule
    self.update(planned=planned_at)
  File "/home/dsmr/dsmr-reader/dsmr_backend/mixins.py", line 200, in update
    self.save(update_fields=updated_fields.keys())
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/base.py", line 754, in save
    force_update=force_update, update_fields=update_fields)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/base.py", line 792, in save_base
    force_update, using, update_fields,
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/base.py", line 873, in _save_table
    forced_update)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/base.py", line 926, in _do_update
    return filtered._update(values) > 0
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/query.py", line 803, in _update
    return query.get_compiler(self.db).execute_sql(CURSOR)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1522, in execute_sql
    cursor = super().execute_sql(result_type)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/models/sql/compiler.py", line 1154, in execute_sql
    cursor = self.connection.cursor()
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/utils/asyncio.py", line 26, in inner
    return func(*args, **kwargs)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/base/base.py", line 259, in cursor
    return self._cursor()
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/base/base.py", line 237, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/utils.py", line 90, in __exit__
    raise dj_exc_value.with_traceback(traceback) from exc_value
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/base/base.py", line 237, in _cursor
    return self._prepare_cursor(self.create_cursor(name))
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/utils/asyncio.py", line 26, in inner
    return func(*args, **kwargs)
  File "/home/dsmr/.virtualenvs/dsmrreader/lib/python3.7/site-packages/django/db/backends/postgresql/base.py", line 236, in create_cursor
    cursor = self.connection.cursor()
django.db.utils.InterfaceError: connection already closed

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

DSMR-reader version

4.19

DSMR-reader platform

Native (e.g. manual installation)

Debug info dump

<!-- COPY OUTPUT BELOW -->


DSMR-READER
    App / Python / Database                                                       v4.19 / v3.7.3 / postgresql
    BE sleep / DL sleep / Retention / Override                                     2.0s / 0.5s / 672h / False
    Latest telegram version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                            2277950
    Consumption records electricity / gas (est.)                                               121808 / 88535

UNRESOLVED ISSUES
    Database growing large: 1552 MB, consider data cleanup (if not already enabled)                          54 seconds ago
    Too many unprocessed readings: 52848                                                         16 hours ago

POSTGRESQL SIZE OF LARGEST TABLES (> 500 MB)
    public.dsmr_datalogger_dsmrreading                                                                1267 MB


<!-- COPY OUTPUT ABOVE -->

[dennissiemensma]

Het lijkt in de DB te zitten, maar de fout is niet heel helder. Het zou ook aan de hoeveelheid data kunnen liggen, in combinatie met de lage datalogger sleep.
Er is echter geen zwart-witte grens voor wanneer de performance er onder lijdt, gezien dat ook deels aan de hardware ligt.

Je kunt dit nog even eenmalig proberen om te zien of die meldingen over grootte weggaan:

sudo su - postgres
vacuumdb -f -v -z -d dsmrreader

Verder kun je het beste in de logs van PostgreSQL zelf kijken. Gezien de DB server "opeens " stopt.

[mkruiver]

Potverdorie, het stofzuigen heeft geholpen!

DSMR-READER
    App / Python / Database                                                       v4.19 / v3.7.3 / postgresql
    BE sleep / DL sleep / Retention / Override                                     2.0s / 0.5s / 672h / False
    Latest telegram version read / Parser settings                                                 "50" / "4"

DATA
    Telegrams total (est.)                                                                            2305610
    Consumption records electricity / gas (est.)                                               122065 / 89025

POSTGRESQL SIZE OF LARGEST TABLES (> 500 MB)
    public.dsmr_datalogger_dsmrreading                                                                 508 MB

[dennissiemensma]

Heeft dat ook direct de fouten opgelost? Dat had ik niet verwacht nl.