Bug 46054 - database connection error not logged
database connection error not logged
Status: RESOLVED FIXED
Product: UCS@school
Classification: Unclassified
Component: HTTP-API (Kelvin)
UCS@school 4.4
Other Linux
: P5 normal (vote)
: ---
Assigned To: Toni Röhmeyer
Daniel Tröder
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2018-01-16 15:01 CET by Daniel Tröder
Modified: 2020-09-09 12:09 CEST (History)
3 users (show)

See Also:
What kind of report is it?: Bug Report
What type of bug is this?: 3: Simply Wrong: The implementation doesn't match the docu
Who will be affected by this bug?: 2: Will only affect a few installed domains
How will those affected feel about the bug?: 2: A Pain – users won’t like this once they notice it
User Pain: 0.069
Enterprise Customer affected?:
School Customer affected?: Yes
ISV affected?:
Waiting Support:
Flags outvoted (downgraded) after PO Review:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Daniel Tröder univentionstaff 2018-01-16 15:01:27 CET
If the HTTP-API backend cannot reach or authenticate with the database, the reason for the error is not logged.

On a customers system PostgreSQL 9.1 and 9.4 were both installed (see Bug #44160). The ucs-school-import expects PostgreSQL 9.4, but 9.1 was running and starting 9.4 failed.

When the HTTP-API was being used, it returned a HTTP 500, but no error message was logged anywhere. I would have expected /var/log/gunicorn/ucs-school-import.log

When using the Django shell, the following traceback was created (which lead to discovering the DB problem):

root@master:~# /usr/share/pyshared/ucsschool/http_api/manage.py shell
Python 2.7.9 (default, Jun 29 2016, 13:08:31)
[GCC 4.9.2] on linux2
Type "help", "copyright", "credits" or "license" for more information.
(InteractiveConsole)
>>>
>>>
>>> from ucsschool.http_api.import_api.models import School
>>> School.objects.all()
Traceback (most recent call last):
  File "<console>", line 1, in <module>
  File "/usr/lib/python2.7/dist-packages/django/db/models/query.py", line 138, in __repr__
    data = list(self[:REPR_OUTPUT_SIZE + 1])
  File "/usr/lib/python2.7/dist-packages/django/db/models/query.py", line 162, in __iter__
    self._fetch_all()
  File "/usr/lib/python2.7/dist-packages/django/db/models/query.py", line 965, in _fetch_all
    self._result_cache = list(self.iterator())
  File "/usr/lib/python2.7/dist-packages/django/db/models/query.py", line 238, in iterator
    results = compiler.execute_sql()
  File "/usr/lib/python2.7/dist-packages/django/db/models/sql/compiler.py", line 838, in execute_sql
    cursor = self.connection.cursor()
  File "/usr/lib/python2.7/dist-packages/django/db/backends/base/base.py", line 164, in cursor
    cursor = self.make_cursor(self._cursor())
  File "/usr/lib/python2.7/dist-packages/django/db/backends/base/base.py", line 135, in _cursor
    self.ensure_connection()
  File "/usr/lib/python2.7/dist-packages/django/db/backends/base/base.py", line 130, in ensure_connection
    self.connect()
  File "/usr/lib/python2.7/dist-packages/django/db/utils.py", line 100, in __exit__
    six.reraise(dj_exc_type, dj_exc_value, traceback)
  File "/usr/lib/python2.7/dist-packages/django/db/backends/base/base.py", line 130, in ensure_connection
    self.connect()
  File "/usr/lib/python2.7/dist-packages/django/db/backends/base/base.py", line 119, in connect
    self.connection = self.get_new_connection(conn_params)
  File "/usr/lib/python2.7/dist-packages/django/db/backends/postgresql_psycopg2/base.py", line 176, in get_new_connection
    connection = Database.connect(**conn_params)
  File "/usr/lib/python2.7/dist-packages/psycopg2/__init__.py", line 164, in connect
    conn = _connect(dsn, connection_factory=connection_factory, async=async)
OperationalError: FATAL:  Passwort-Authentifizierung für Benutzer »importhttpapi« fehlgeschlagen
FATAL:  Passwort-Authentifizierung für Benutzer »importhttpapi« fehlgeschlagen

---

Change the gunicorn/Django configuration so that DB errors are logged.
Comment 1 Toni Röhmeyer univentionstaff 2020-09-06 13:08:40 CEST
As defined in /ucs-school-import/conffiles/etc/gunicorn.d/ucs-school-import,
the log is not saved under /var/log/gunicorn/ucs-school-import.log but in /var/log/univention/ucs-school-import/gunicorn_access.log

The corresponding log entry looks like this:
127.0.0.1 - Administrator [04/Sep/2020:08:06:04 +0200] "GET /v1/ HTTP/1.1" 500 27 "-" "python-requests/2.12.4"
Comment 2 Daniel Tröder univentionstaff 2020-09-07 16:58:29 CEST
That log entry is not helpful.

Please try to find a way for a Django (REST API) app to log a DB access error to a logfile and to return a meaningful message together with the HTTP 500 status.
Comment 3 Toni Röhmeyer univentionstaff 2020-09-09 12:09:26 CEST
Sorry the example log entry from comment1 is actually taken from the gunicorn_access.log.

However, the gunicorn_error.log DOES contain the http errors IF the UCRV ucsschool/import/http_api/wsgi_server_loglevel is set to "error".

This can be seen in the gunicorn conf in 
conffiles/etc/gunicorn.d/ucs-school-import
The current default value there is "debug".

If you want to test this, make sure to restart the gunicorn workers after code change (by setting ucsschool/import/http_api/django_debug=True)

Afterwards, /var/log/univention/ucs-school-import/gunicorn_error.log should contain the corresponding traceback.