Internal Server Error: /hyperkitty/list/my@lists.domain.eu/pop-threads
Dear all,
I've setup my own instance of Hyperkitty working as archiver of a Mailman 3 server. It works fine but, sometimes, I get an email of a Django error:
Internal Server Error: /hyperkitty/list/my@lists.domain.eu/pop-threads
KeyError at /hyperkitty/list/my@lists.domain.eu/pop-threads 'file' Request Method: GET Django Version: 2.2.12 Python Executable: /usr/bin/python3 Python Version: 3.7.3 Traceback:
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py" in inner 34. response = get_response(request)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py" in _get_response 115. response = self.process_exception_by_middleware(e, request)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py" in _get_response 113. response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/usr/local/lib/python3.7/dist-packages/hyperkitty/lib/view_helpers.py" in inner 129. if not is_mlist_authorized(request, mlist):
File "/usr/local/lib/python3.7/dist-packages/hyperkitty/lib/view_helpers.py" in is_mlist_authorized 146. if mlist.list_id in get_subscriptions(request.user):
File "/usr/local/lib/python3.7/dist-packages/django_mailman3/lib/mailman.py" in get_subscriptions 130. _get_value, 60, version=2) # 1 minute
File "/usr/local/lib/python3.7/dist-packages/django/core/cache/backends/base.py" in get_or_set 167. default = default()
File "/usr/local/lib/python3.7/dist-packages/django_mailman3/lib/mailman.py" in _get_value 122. for member in mm_user.subscriptions
File "/usr/local/lib/python3.7/dist-packages/mailmanclient/restobjects/user.py" in subscriptions 66. 'members/find', data={'subscriber': address})
File "/usr/local/lib/python3.7/dist-packages/mailmanclient/restbase/connection.py" in call 112. error_msg, response, None)
During handling of the above exception (HTTP Error 500: <html> <head> <title>Internal Server Error</title> </head> <body> <h1><p>Internal Server Error</p></h1>
</body> </html> ), another exception occurred:
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py" in inner 34. response = get_response(request)
File "/usr/local/lib/python3.7/dist-packages/django/utils/deprecation.py" in __call__ 94. response = response or self.get_response(request)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py" in inner 36. response = response_for_exception(request, exc)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py" in response_for_exception 95. exc_info=sys.exc_info(),
File "/usr/local/lib/python3.7/dist-packages/django/utils/log.py" in log_response 228. exc_info=exc_info,
File "/usr/lib/python3.7/logging/__init__.py" in error 1412. self._log(ERROR, msg, args, **kwargs)
File "/usr/lib/python3.7/logging/__init__.py" in _log 1519. self.handle(record)
File "/usr/lib/python3.7/logging/__init__.py" in handle 1529. self.callHandlers(record)
File "/usr/lib/python3.7/logging/__init__.py" in callHandlers 1591. hdlr.handle(record)
File "/usr/lib/python3.7/logging/__init__.py" in handle 905. self.emit(record)
File "/usr/local/lib/python3.7/dist-packages/django/utils/log.py" in emit 119. reporter = ExceptionReporter(request, is_email=True, *exc_info)
File "/usr/local/lib/python3.7/dist-packages/django/views/debug.py" in __init__ 254. self.template_info = getattr(self.exc_value, 'template_debug', None)
File "/usr/lib/python3.7/tempfile.py" in __getattr__ 614. file = self.__dict__['file']
Exception Type: KeyError at /hyperkitty/list/my@lists.domain.eu/pop-threads Exception Value: 'file' Request information: USER: myuser
GET: No GET data
POST: No POST data
FILES: No FILES data
Where did I go wrong?
Best, Marco
On 2/21/21 3:09 AM, Marco Marinello wrote:
Dear all,
I've setup my own instance of Hyperkitty working as archiver of a Mailman 3 server. It works fine but, sometimes, I get an email of a Django error:
Internal Server Error: /hyperkitty/list/my@lists.domain.eu/pop-threads
KeyError at /hyperkitty/list/my@lists.domain.eu/pop-threads 'file'
The above is not the issue. It results from Django trying to look up a log file in the LOGGING configuration.
Request Method: GET Django Version: 2.2.12 Python Executable: /usr/bin/python3 Python Version: 3.7.3 Traceback:
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/exception.py" in inner 34. response = get_response(request)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py" in _get_response 115. response = self.process_exception_by_middleware(e, request)
File "/usr/local/lib/python3.7/dist-packages/django/core/handlers/base.py" in _get_response 113. response = wrapped_callback(request, *callback_args, **callback_kwargs)
File "/usr/local/lib/python3.7/dist-packages/hyperkitty/lib/view_helpers.py" in inner 129. if not is_mlist_authorized(request, mlist):
File "/usr/local/lib/python3.7/dist-packages/hyperkitty/lib/view_helpers.py" in is_mlist_authorized 146. if mlist.list_id in get_subscriptions(request.user):
File "/usr/local/lib/python3.7/dist-packages/django_mailman3/lib/mailman.py" in get_subscriptions 130. _get_value, 60, version=2) # 1 minute
File "/usr/local/lib/python3.7/dist-packages/django/core/cache/backends/base.py" in get_or_set 167. default = default()
File "/usr/local/lib/python3.7/dist-packages/django_mailman3/lib/mailman.py" in _get_value 122. for member in mm_user.subscriptions
File "/usr/local/lib/python3.7/dist-packages/mailmanclient/restobjects/user.py" in subscriptions 66. 'members/find', data={'subscriber': address})
File "/usr/local/lib/python3.7/dist-packages/mailmanclient/restbase/connection.py" in call 112. error_msg, response, None)
During handling of the above exception (HTTP Error 500: <html> <head> <title>Internal Server Error</title> </head> <body> <h1><p>Internal Server Error</p></h1>
</body> </html>
What's happening is HyperKitty is trying to determine if the request comes from a list member, and that throws an exception resulting in the 500. What's in Mailman core's mailman.log? Is Mailman core's REST API even accessible from this HyperKitty instance.
If not, you can't support private archives and will probably have other issues?
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
Dear Mark,
thank you for your answer. I can confirm my Hyperkitty works just fine for archiving messages. I can even confirm Hyperkitty can reach Mailman REST API. I haven't touched the LOGGING configuration but here you go (can even confirm hyperkitty.log is filled correctly with logs):
# A sample logging configuration. The only tangible logging # performed by this configuration is to send an email to # the site admins on every HTTP 500 error when DEBUG=False. # See http://docs.djangoproject.com/en/dev/topics/logging for # more details on how to customize your logging configuration. LOGGING = { 'version': 1, 'disable_existing_loggers': False, 'filters': { 'require_debug_false': { '()': 'django.utils.log.RequireDebugFalse' } }, 'handlers': { 'mail_admins': { 'level': 'ERROR', 'filters': ['require_debug_false'], 'class': 'django.utils.log.AdminEmailHandler' }, 'file':{ 'level': 'INFO', #'class': 'logging.handlers.RotatingFileHandler', 'class': 'logging.handlers.WatchedFileHandler', 'filename': os.path.join(BASE_DIR, 'hyperkitty.log'), 'formatter': 'verbose', }, }, 'loggers': { 'django.request': { 'handlers': ['mail_admins', 'file'], 'level': 'ERROR', 'propagate': True, }, 'django': { 'handlers': ['file'], 'level': 'ERROR', 'propagate': True, }, 'hyperkitty': { 'handlers': ['file'], 'level': 'DEBUG', 'propagate': True, }, }, 'formatters': { 'verbose': { 'format': '%(levelname)s %(asctime)s %(process)d %(name)s %(message)s' }, 'simple': { 'format': '%(levelname)s %(message)s' }, }, #'root': { # 'handlers': ['file'], # 'level': 'INFO', #}, }
In mailman.log, instead, it seems like there's some issue with PostgreSQL
[2021-02-21 18:57:19 +0000] [11685] [ERROR] Error handling request /3.1/users/user@example.com Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle self.handle_request(listener, req, client, addr) File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request respiter = self.wsgi(environ, resp.start_response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 50, in wrapper rtn = function(*args, **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__ return super().__call__(environ, start_response) File "falcon/api.py", line 274, in falcon.api.API.__call__ File "falcon/api.py", line 269, in falcon.api.API.__call__ File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 211, in on_get okay(response, self._resource_as_json(self._user)) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/helpers.py", line 124, in _resource_as_json resource = self._resource_as_dict(resource) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 130, in _resource_as_dict user_id = self.api.from_uuid(user.user_id) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/core/api.py", line 78, in from_uuid return uuid.hex AttributeError: 'NoneType' object has no attribute 'hex' [21/Feb/2021:18:57:19 +0000] "GET /3.1/users/user@example.com HTTP/1.1" 500 0 "-" "-" [2021-02-21 18:57:19 +0000] [11685] [ERROR] Error handling request /3.1/users/eeb2ainoh0ki8ohL3Renahseiph7AePh Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle self.handle_request(listener, req, client, addr) File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request respiter = self.wsgi(environ, resp.start_response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 50, in wrapper rtn = function(*args, **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__ return super().__call__(environ, start_response) File "falcon/api.py", line 274, in falcon.api.API.__call__ File "falcon/api.py", line 269, in falcon.api.API.__call__ File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 208, in on_get if self._user is None: File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 204, in _user return user_manager.get_user_by_id(user_id) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 85, in wrapper return function(args[0], config.db.store, *args[1:], **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/model/usermanager.py", line 96, in get_user_by_id return users.one() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3458, in one ret = self.one_or_none() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3427, in one_or_none ret = list(self) File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 101, in instances cursor.close() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__ exc_value, with_traceback=exc_tb, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in instances rows = [proc(row) for row in fetch] File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp> rows = [proc(row) for row in fetch] File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 525, in _instance tuple([row[column] for column in pk_cols]), File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 525, in <listcomp> tuple([row[column] for column in pk_cols]), File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 686, in _key_fallback replace_context=err, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception sqlalchemy.exc.NoSuchColumnError: "Could not locate column in row for column 'user.id'" [2021-02-21 18:57:19 +0000] [16321] [ERROR] Error handling request /3.1/users/Cautah7jael5nieri0jaiRooVi6eech9/addresses Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle self.handle_request(listener, req, client, addr) File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request respiter = self.wsgi(environ, resp.start_response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 50, in wrapper rtn = function(*args, **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__ return super().__call__(environ, start_response) File "falcon/api.py", line 252, in falcon.api.API.__call__ File "falcon/api.py", line 249, in falcon.api.API.__call__ File "falcon/api.py", line 681, in falcon.api.API._get_responder File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 106, in find attribute = getattr(resource, name, MISSING) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 204, in _user return user_manager.get_user_by_id(user_id) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 85, in wrapper return function(args[0], config.db.store, *args[1:], **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/model/usermanager.py", line 94, in get_user_by_id if users.count() == 0: File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3771, in count return self.from_self(col).scalar() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3491, in scalar ret = self.one() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3458, in one ret = self.one_or_none() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3427, in one_or_none ret = list(self) File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 101, in instances cursor.close() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__ exc_value, with_traceback=exc_tb, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 61, in instances for query_entity in query._entities File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 61, in <listcomp> for query_entity in query._entities File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 4817, in row_processor getter = result._getter(column) File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 783, in _getter return getter(key, raiseerr) File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 704, in _getter ret = self._key_fallback(key, None, raiseerr) File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 686, in _key_fallback replace_context=err, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception sqlalchemy.exc.NoSuchColumnError: "Could not locate column in row for column 'count(*)'" [21/Feb/2021:18:57:19 +0000] "GET /3.1/users/Cautah7jael5nieri0jaiRooVi6eech9 HTTP/1.1" 500 0 "-" "-" [2021-02-21 18:57:19 +0000] [11685] [ERROR] Error handling request /3.1/members/find Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle self.handle_request(listener, req, client, addr) File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request respiter = self.wsgi(environ, resp.start_response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 50, in wrapper rtn = function(*args, **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__ return super().__call__(environ, start_response) File "falcon/api.py", line 274, in falcon.api.API.__call__ File "falcon/api.py", line 269, in falcon.api.API.__call__ File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/members.py", line 460, in on_post return self._find(request, response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/members.py", line 488, in _find collection = resource._make_collection(request, fields) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/helpers.py", line 182, in _make_collection entries = [as_dict(resource) for resource in collection] File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/helpers.py", line 182, in <listcomp> entries = [as_dict(resource) for resource in collection] File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/utilities/queries.py", line 47, in __iter__ yield from self._query File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 101, in instances cursor.close() File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 69, in __exit__ exc_value, with_traceback=exc_tb, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in instances rows = [proc(row) for row in fetch] File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 81, in <listcomp> rows = [proc(row) for row in fetch] File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 525, in _instance tuple([row[column] for column in pk_cols]), File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/orm/loading.py", line 525, in <listcomp> tuple([row[column] for column in pk_cols]), File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/engine/result.py", line 686, in _key_fallback replace_context=err, File "/opt/mailman/venv/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 178, in raise_ raise exception sqlalchemy.exc.NoSuchColumnError: "Could not locate column in row for column '%(140001824334904 anon)s.%(140001822909888 anon)s_member_id'" [21/Feb/2021:18:57:19 +0000] "POST /3.1/members/find HTTP/1.1" 500 0 "-" "-"
-Marco
On 2/22/21 8:26 AM, Marco Marinello wrote:
Dear Mark,
thank you for your answer. I can confirm my Hyperkitty works just fine for archiving messages. I can even confirm Hyperkitty can reach Mailman REST API. I haven't touched the LOGGING configuration but here you go (can even confirm hyperkitty.log is filled correctly with logs):
What I was trying to say is this
KeyError at /hyperkitty/list/my@lists.domain.eu/pop-threads 'file'
exception often occurs in messages sent by Django to site admins and is never actually relates to the real problem and should just be ignored.
In mailman.log, instead, it seems like there's some issue with PostgreSQL
[2021-02-21 18:57:19 +0000] [11685] [ERROR] Error handling request /3.1/users/user@example.com Traceback (most recent call last): File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 134, in handle self.handle_request(listener, req, client, addr) File "/opt/mailman/venv/lib64/python3.6/site-packages/gunicorn/workers/sync.py", line 175, in handle_request respiter = self.wsgi(environ, resp.start_response) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/database/transaction.py", line 50, in wrapper rtn = function(*args, **kws) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/wsgiapp.py", line 193, in __call__ return super().__call__(environ, start_response) File "falcon/api.py", line 274, in falcon.api.API.__call__ File "falcon/api.py", line 269, in falcon.api.API.__call__ File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 211, in on_get okay(response, self._resource_as_json(self._user)) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/helpers.py", line 124, in _resource_as_json resource = self._resource_as_dict(resource) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 130, in _resource_as_dict user_id = self.api.from_uuid(user.user_id) File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/core/api.py", line 78, in from_uuid return uuid.hex AttributeError: 'NoneType' object has no attribute 'hex' [21/Feb/2021:18:57:19 +0000] "GET /3.1/users/user@example.com HTTP/1.1" 500 0 "-" "-"
I think this is the real issue. HyperKitty is trying to get the user information from core for user@example.com and this is throwing the AttributeError resulting in the 500. This is most likely some kind of database issue.
at this point
File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 211, in on_get okay(response, self._resource_as_json(self._user))
self._user is not None, but at this point
File "/opt/mailman/venv/lib64/python3.6/site-packages/mailman/rest/users.py", line 130, in _resource_as_dict user_id = self.api.from_uuid(user.user_id)
user.user_id is None.
If I were you, I would look at the database. First, I would find the entry in the address table. I.e.,
select user_id from address where email = 'user@example.com';
then the uid
select uid from uid where id = <the user_id from above>
I suspect there is no uid entry for this id.
You might get more information from
$ /opt/mailman/mm/bin/mailman shell Welcome to the GNU Mailman shell Use commit() to commit changes. Use abort() to discard changes since the last commit. Exit with ctrl+D does an implicit commit() but exit() does not.
um = getUtility(IUserManager) usr = um.get_user('user@example.com')
which I suspect will also throw an exception, but if not
usr.id
should return the id found by select user_id from address where email = 'user@example.com';
and
usr.user_id
should return the uiud which should not be None
-- Mark Sapiro <mark@msapiro.net> The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan
participants (2)
-
Marco Marinello -
Mark Sapiro