Details
-
Bug
-
Resolution: Done
-
Critical
-
quay-v3.6.2, quay-v3.7.0, quay-v3.7.1
Description
Under certain circumstances, the Usage Logs history will error out with a 500. This is caused by a wrongly terminated JSON metadata logged in logentry3 table. When decoding the logs, the following Python trace is observed:
gunicorn-web stdout | 2022-02-04 09:54:38,073 [222] [ERROR] [gunicorn.error] Error handling request /api/v1/repository/library/python/logs?starttime=1%2F28%2F2022&endtime=2%2F4%2F2022 gunicorn-web stdout | Traceback (most recent call last): gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/gunicorn/workers/base_async.py", line 55, in handle gunicorn-web stdout | self.handle_request(listener_name, req, client, addr) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/gunicorn/workers/ggevent.py", line 143, in handle_request gunicorn-web stdout | super().handle_request(listener_name, req, sock, addr) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/gunicorn/workers/base_async.py", line 106, in handle_request gunicorn-web stdout | respiter = self.wsgi(environ, resp.start_response) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2463, in __call__ gunicorn-web stdout | return self.wsgi_app(environ, start_response) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/werkzeug/middleware/proxy_fix.py", line 232, in __call__ gunicorn-web stdout | return self.app(environ, start_response) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2449, in wsgi_app gunicorn-web stdout | response = self.handle_exception(e) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask_restful/__init__.py", line 269, in error_router gunicorn-web stdout | return original_handler(e) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1866, in handle_exception gunicorn-web stdout | reraise(exc_type, exc_value, tb) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/_compat.py", line 38, in reraise gunicorn-web stdout | raise value.with_traceback(tb) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 2446, in wsgi_app gunicorn-web stdout | response = self.full_dispatch_request() gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1951, in full_dispatch_request gunicorn-web stdout | rv = self.handle_user_exception(e) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask_restful/__init__.py", line 269, in error_router gunicorn-web stdout | return original_handler(e) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1820, in handle_user_exception gunicorn-web stdout | reraise(exc_type, exc_value, tb) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/_compat.py", line 38, in reraise gunicorn-web stdout | raise value.with_traceback(tb) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1949, in full_dispatch_request gunicorn-web stdout | rv = self.dispatch_request() gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/app.py", line 1935, in dispatch_request gunicorn-web stdout | return self.view_functions[rule.endpoint](**req.view_args) gunicorn-web stdout | File "/quay-registry/endpoints/decorators.py", line 212, in wrapper gunicorn-web stdout | return func(*args, **kwargs) gunicorn-web stdout | File "/quay-registry/auth/decorators.py", line 65, in wrapper gunicorn-web stdout | return func(*args, **kwargs) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask_restful/utils/cors.py", line 35, in wrapped_function gunicorn-web stdout | resp = make_response(f(*args, **kwargs)) gunicorn-web stdout | File "/quay-registry/endpoints/csrf.py", line 73, in wrapper gunicorn-web stdout | resp = func(*args, **kwargs) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask_restful/__init__.py", line 458, in wrapper gunicorn-web stdout | resp = resource(*args, **kwargs) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask/views.py", line 89, in view gunicorn-web stdout | return self.dispatch_request(*args, **kwargs) gunicorn-web stdout | File "/usr/local/lib/python3.8/site-packages/flask_restful/__init__.py", line 573, in dispatch_request gunicorn-web stdout | resp = meth(*args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/decorators.py", line 141, in wrapper gunicorn-web stdout | return func(*args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/api/__init__.py", line 241, in wrapper gunicorn-web stdout | return func(namespace, repository, *args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/decorators.py", line 120, in wrapper gunicorn-web stdout | return func(*args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/api/__init__.py", line 295, in wrapped gunicorn-web stdout | return func(self, namespace, repository, *args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/api/__init__.py", line 228, in wrapper gunicorn-web stdout | return func(self, *args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/api/__init__.py", line 205, in wrapper gunicorn-web stdout | (result, next_page_token) = func(self, *args, **kwargs) gunicorn-web stdout | File "/quay-registry/endpoints/api/logs.py", line 140, in get gunicorn-web stdout | return _get_logs( gunicorn-web stdout | File "/quay-registry/endpoints/api/logs.py", line 94, in _get_logs gunicorn-web stdout | "logs": [log.to_dict(avatar, include_namespace) for log in log_entry_page.logs], gunicorn-web stdout | File "/quay-registry/endpoints/api/logs.py", line 94, in <listcomp> gunicorn-web stdout | "logs": [log.to_dict(avatar, include_namespace) for log in log_entry_page.logs], gunicorn-web stdout | File "/quay-registry/data/logs_model/datatypes.py", line 146, in to_dict gunicorn-web stdout | "metadata": json.loads(self.metadata_json or "{}"), gunicorn-web stdout | File "/usr/lib64/python3.8/json/__init__.py", line 357, in loads gunicorn-web stdout | return _default_decoder.decode(s) gunicorn-web stdout | File "/usr/lib64/python3.8/json/decoder.py", line 337, in decode gunicorn-web stdout | obj, end = self.raw_decode(s, idx=_w(s, 0).end()) gunicorn-web stdout | File "/usr/lib64/python3.8/json/decoder.py", line 353, in raw_decode gunicorn-web stdout | obj, end = self.scan_once(s, idx) gunicorn-web stdout | json.decoder.JSONDecodeError: Unterminated string starting at: line 1 column 9595 (char 9594)
It seems that either the JSON metadata text field is not long enough or the buffer we use to write in before data is dumped to the table is not big enough when DEBUGLOG=true on repo mirror pods. This usually happens on manifest lists composed of many layer and many individual images.. To reproduce:
1) set up a mirroring repo inisde Quay to mirror docker.io/library/python repository.
2) try to mirror the latest tag.
The issue does not seem to happen when debug logging is turned off.
The only workaround to resolve the problem is to delete logentry3 table entries connected to the mirror tag successful. This is an example of the operation where the metadata is not correctly terminated:
| 7969 | 70 | 3 | NULL | 2 | 2022-02-02 16:46:48 | NULL | {"verb": "finish", "namespace": "library", "repo": "python", "message": "Source 'docker://docker.io/library/python:latest' successful sync", "tag": "latest", "tags": null, "stdout": "Copying 9 of 9 images in list\nCopying image sha256:023cdc92b5992ff45c68a2509de0872e5e29329655866fa7bf8f9eeb99834b46 (1/9)\nCopying blob /snip \"Skipping blob sha256:e6add0df5305b15260ad899f9e9323807f31c3187e0f96b8839911e4a5d2508f (already present):\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"Checking /v2/library/python/blobs/sha256:5546b7105dfcc19959a05fcd28a9b09d9e4e7f4ef3d8f38f8bb9ccd28c7d057a\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"HEAD https://quay.ibazulic.me/v2/library/python/blobs/sha256:5546b7105dfcc19959a05fcd28a9b09d9e4e7f4ef3d8f38f8bb9ccd28c7d057a\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"... already exists\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"Skipping blob sha256:cca475bd1faac63fb98161ddab9d6899d6835750ab6291cddf7acecbb5a24997 (already present):\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"... already exists\"\ntime=\"2022-02-02T16:46:46Z\" level=debug msg=\"Skipping |
Please check, thanks!
Attachments
Issue Links
- impacts account
-
-
- Closed
-
-
-
- Closed
-
- mentioned on
