psycopg2.DatabaseError errors cause 500 Internal Server Error
Hi, I didn't find any issue (except #627 (closed)) regarding this error so I've decided to create one.
The issue is about PostgreSQL database errors randomly appear in the logs. The errors, unfortunately, don't contain any useful information in them, so the first step might be to add some debug info to them.
Example of an error that happened just recently in one of my servers:
The user was doing some configuration in Postorius at 18:57 when got 500 Internal Server Error as per uwsgi.log:
[pid: 1703|app: 0|req: 2113/3329] 199.16.157.183 () {46 vars in 658 bytes} [Sun Apr 4 18:57:40 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 85 msecs (HTTP/1.1 200) 6 headers in 331 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2114/3330] 17.58.101.25 () {36 vars in 646 bytes} [Sun Apr 4 18:57:45 2021] GET /robots.txt => generated 3951 bytes in 8 msecs (HTTP/1.1 404) 5 headers in 170 bytes (1 switches on core 0)
[pid: 1703|app: 0|req: 2115/3331] 17.58.96.59 () {36 vars in 709 bytes} [Sun Apr 4 18:57:45 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 92 msecs (HTTP/1.1 200) 6 headers in 331 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2117/3332] 34.82.212.79 () {30 vars in 407 bytes} [Sun Apr 4 18:57:46 2021] HEAD /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 98 msecs (HTTP/2.0 200) 6 headers in 331 bytes (1 switches on core 0)
[pid: 1703|app: 0|req: 2118/3333] 34.82.212.79 () {32 vars in 547 bytes} [Sun Apr 4 18:57:46 2021] HEAD /postorius/lists/cpuchain-dev.mailman3.com/ => generated 4191 bytes in 111 msecs (HTTP/2.0 500) 5 headers in 182 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2118/3334] 34.82.212.79 () {32 vars in 561 bytes} [Sun Apr 4 18:57:46 2021] HEAD /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 190 msecs (HTTP/2.0 200) 6 headers in 331 bytes (1 switches on core 0)
[pid: 1703|app: 0|req: 2119/3335] 52.204.27.85 () {36 vars in 493 bytes} [Sun Apr 4 18:57:50 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 83 msecs (HTTP/1.1 200) 6 headers in 331 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2120/3336] 3.217.157.17 () {36 vars in 516 bytes} [Sun Apr 4 18:57:55 2021] GET /robots.txt => generated 3951 bytes in 3 msecs (HTTP/1.1 404) 5 headers in 170 bytes (1 switches on core 0)
[pid: 1703|app: 0|req: 2121/3337] 3.217.157.17 () {36 vars in 580 bytes} [Sun Apr 4 18:57:55 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 90 msecs (HTTP/1.1 200) 6 headers in 331 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2122/3338] 94.130.167.88 () {48 vars in 747 bytes} [Sun Apr 4 18:57:57 2021] GET /robots.txt => generated 3951 bytes in 3 msecs (HTTP/1.1 404) 5 headers in 173 bytes (1 switches on core 0)
[pid: 1703|app: 0|req: 2123/3339] 94.130.167.88 () {48 vars in 811 bytes} [Sun Apr 4 18:57:57 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 118 msecs (HTTP/1.1 200) 6 headers in 334 bytes (1 switches on core 1)
[pid: 1703|app: 0|req: 2124/3340] 192.99.1.145 () {46 vars in 729 bytes} [Sun Apr 4 18:58:28 2021] GET /postorius/lists/cpuchain-dev.mailman3.com/ => generated 6650 bytes in 85 msecs (HTTP/1.1 200) 6 headers in 331 bytes (1 switches on core 0)The error looks like this in mailmanweb.log:
ERROR 2021-04-04 18:57:46,872 1703 postorius Un-handled exception: HTTP Error 500: <html>
<head>
<title>Internal Server Error</title>
</head>
<body>
<h1><p>Internal Server Error</p></h1>
</body>
</html>
Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/django/core/handlers/base.py", line 113, in _get_response
response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/usr/lib/python3.8/site-packages/django/views/generic/base.py", line 71, in view
return self.dispatch(request, *args, **kwargs)
File "/usr/lib/python3.8/site-packages/postorius/views/generic.py", line 68, in dispatch
self.mailing_list = self._get_list(kwargs['list_id'],
File "/usr/lib/python3.8/site-packages/postorius/views/generic.py", line 63, in _get_list
return List.objects.get_or_404(fqdn_listname=list_id)
File "/usr/lib/python3.8/site-packages/postorius/models.py", line 125, in get_or_404
return self.get(*args, **kwargs)
File "/usr/lib/python3.8/site-packages/postorius/models.py", line 110, in get
return method(*args, **kwargs)
File "/usr/lib/python3.8/site-packages/mailmanclient/client.py", line 356, in get_list
response, content = self._connection.call(
File "/usr/lib/python3.8/site-packages/mailmanclient/restbase/connection.py", line 127, in call
raise HTTPError(url, response.status_code,
urllib.error.HTTPError: HTTP Error 500: <html>
<head>
<title>Internal Server Error</title>
</head>
<body>
<h1><p>Internal Server Error</p></h1>
</body>
</html>
ERROR 2021-04-04 18:57:46,933 1703 django.request Internal Server Error: /postorius/lists/cpuchain-dev.mailman3.com/
ERROR 2021-04-04 18:57:46,933 1703 django.request Internal Server Error: /postorius/lists/cpuchain-dev.mailman3.com/And finally, we can map it to the psycopg2.DatabaseError in Core mailman.log:
[04/Apr/2021:18:57:40 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com HTTP/1.1" 200 411 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:40 +0000] "GET /3.1/lists/cpuchain-dev@mailman3.com/config HTTP/1.1" 200 3234 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:40 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com/archivers HTTP/1.1" 200 103 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:40 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com/archivers HTTP/1.1" 200 103 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:45 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com HTTP/1.1" 200 411 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:45 +0000] "GET /3.1/lists/cpuchain-dev@mailman3.com/config HTTP/1.1" 200 3234 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:45 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com/archivers HTTP/1.1" 200 103 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:45 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com/archivers HTTP/1.1" 200 103 "-" "GNU Mailman REST client v3.3.2"
[2021-04-04 18:57:46 +0000] [50] [ERROR] Error handling request /3.1/lists/cpuchain-dev.mailman3.com
Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2336, in _wrap_pool_connect
return fn()
File "/usr/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 364, in connect
return _ConnectionFairy._checkout(self)
File "/usr/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 809, in _checkout
result = pool._dialect.do_ping(fairy.connection)
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 575, in do_ping
cursor.execute(self._dialect_specific_select_one)
psycopg2.DatabaseError: error with status PGRES_TUPLES_OK and no message from the libpq
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 135, in handle
self.handle_request(listener, req, client, addr)
File "/usr/lib/python3.8/site-packages/gunicorn/workers/sync.py", line 176, in handle_request
respiter = self.wsgi(environ, resp.start_response)
File "/usr/lib/python3.8/site-packages/mailman/database/transaction.py", line 50, in wrapper
rtn = function(*args, **kws)
File "/usr/lib/python3.8/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__
return super().__call__(environ, start_response)
File "/usr/lib/python3.8/site-packages/falcon/api.py", line 249, in __call__
responder, params, resource, req.uri_template = self._get_responder(req)
File "/usr/lib/python3.8/site-packages/falcon/api.py", line 681, in _get_responder
route = self._router_search(path, req=req)
File "/usr/lib/python3.8/site-packages/mailman/rest/wsgiapp.py", line 126, in find
result = attribute(context, segments)
File "/usr/lib/python3.8/site-packages/mailman/rest/root.py", line 227, in lists
return AList(list_identifier), segments
File "/usr/lib/python3.8/site-packages/mailman/rest/lists.py", line 191, in __init__
self._mlist = manager.get_by_list_id(list_identifier)
File "/usr/lib/python3.8/site-packages/mailman/database/transaction.py", line 85, in wrapper
return function(args[0], config.db.store, *args[1:], **kws)
File "/usr/lib/python3.8/site-packages/mailman/model/listmanager.py", line 71, in get_by_list_id
return store.query(MailingList).filter_by(_list_id=list_id).first()
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3429, in first
ret = list(self[0:1])
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3203, in __getitem__
return list(res)
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3535, in __iter__
return self._execute_and_instances(context)
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3556, in _execute_and_instances
conn = self._get_bind_args(
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3571, in _get_bind_args
return fn(
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/query.py", line 3550, in _connection_from_session
conn = self.session.connection(**kw)
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 1142, in connection
return self._connection_for_bind(
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 1150, in _connection_for_bind
return self.transaction._connection_for_bind(
File "/usr/lib/python3.8/site-packages/sqlalchemy/orm/session.py", line 433, in _connection_for_bind
conn = bind._contextual_connect()
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2302, in _contextual_connect
self._wrap_pool_connect(self.pool.connect, None),
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2339, in _wrap_pool_connect
Connection._handle_dbapi_exception_noconnection(
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1583, in _handle_dbapi_exception_noconnection
util.raise_(
File "/usr/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
raise exception
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2336, in _wrap_pool_connect
return fn()
File "/usr/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 364, in connect
return _ConnectionFairy._checkout(self)
File "/usr/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 809, in _checkout
result = pool._dialect.do_ping(fairy.connection)
File "/usr/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 575, in do_ping
cursor.execute(self._dialect_specific_select_one)
sqlalchemy.exc.DatabaseError: (psycopg2.DatabaseError) error with status PGRES_TUPLES_OK and no message from the libpq
(Background on this error at: http://sqlalche.me/e/13/4xp6)
[04/Apr/2021:18:57:46 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com HTTP/1.1" 500 0 "-" "-"
[04/Apr/2021:18:57:46 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com HTTP/1.1" 200 411 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:46 +0000] "GET /3.1/lists/cpuchain-dev@mailman3.com/config HTTP/1.1" 200 3234 "-" "GNU Mailman REST client v3.3.2"
[04/Apr/2021:18:57:46 +0000] "GET /3.1/lists/cpuchain-dev.mailman3.com/archivers HTTP/1.1" 200 103 "-" "GNU Mailman REST client v3.3.2"I suppose this is a serious issue that affects all installations with PostgreSQL database (which is a recommended one).
I would be happy to collect more info on the server if you help me to find where to look.
Thank you