Force all API loggers to be structured

[sarayourfriend]

Fixes

Related to https://github.com/WordPress/openverse-infrastructure/issues/895

Description

The API logging after #4263 was a mix of structured and unstructured logs. This makes it basically impossible to reliably parse multi-line logs, because there was a mix of log-line start indicators (either a datestamp or an opening curly brace).

This PR forces all logging to be structured. There are a couple leaks during startup, but I don't think there's a good way to fix those that isn't convoluted.

In doing this, I read through a lot of the structlog documentation and refamiliarised myself with the Python logging config docs as well. We were doing a lot of unnecessary configuration and I was able to remove a significant amount of duplicative or unused configuration. I've entirely removed the plain "console" logger configuration.

This PR is critical because without it, our production logs are next to useless when queried. This will not fix the issue, as we also need to make a configuration change to tell CloudWatch to split logs on the opening curly brace instead, but that will be in a PR in the infrastructure repository.

cc @dhruvkb as the original implementer of the structlog in the API. We'll need to keep this in mind when adding structured logging to other apps as well.

Testing Instructions

Set LOG_PROCESSOR=json in api/.env. Then run the API with the new environment variable using just down web && just api/up and then view the logs with just logs web.

Make requests and confirm the following:

1. All logs are structured, even ones that previously were not (e.g., Django logs, Elasticsearch logs, uvicorn logs, error logs)
2. Request logs for the healthcheck endpoint are suppressed (don't show up in the logs)
3. django.request and uvicorn.access logs are suppressed (comment these out of the set if you want to see what it looks like when they are not suppressed and compare)
4. Modify the API code to force an exception to be raised at some point and confirm that the stacktrace and everything is structured. Example below where I raised a ValueError in the get_queryset of the base media view:

{"code": 500, "request": "GET /v1/images/", "event": "request_failed", "timestamp": "2024-05-15T03:41:20.109814Z", "user_id": null, "ip": "172.20.0.1", "request_id": "23c6d1b3-c849-4091-943d-6ff272a0cf0d", "logger": "django_structlog.middlewares.request", "level": "error", "filename": "request.py", "lineno": 197, "func_name": "process_exception", "exception": "Traceback (most recent call last):\n  File \"/.venv/lib/python3.11/site-packages/asgiref/sync.py\", line 518, in thread_handler\n    raise exc_info[1]\n  File \"/.venv/lib/python3.11/site-packages/django/core/handlers/base.py\", line 253, in _get_response_async\n    response = await wrapped_callback(\n               ^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/adrf/viewsets.py\", line 120, in async_view\n    return await self.dispatch(request, *args, **kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/adrf/views.py\", line 73, in async_dispatch\n    response = self.handle_exception(exc)\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/rest_framework/views.py\", line 469, in handle_exception\n    self.raise_uncaught_exception(exc)\n  File \"/.venv/lib/python3.11/site-packages/rest_framework/views.py\", line 480, in raise_uncaught_exception\n    raise exc\n  File \"/.venv/lib/python3.11/site-packages/adrf/views.py\", line 70, in async_dispatch\n    response = await sync_to_async(handler)(request, *args, **kwargs)\n               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/asgiref/sync.py\", line 468, in __call__\n    ret = await asyncio.shield(exec_coro)\n          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/asgiref/current_thread_executor.py\", line 40, in run\n    result = self.fn(*self.args, **self.kwargs)\n             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/asgiref/sync.py\", line 522, in thread_handler\n    return func(*args, **kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^\n  File \"/.venv/lib/python3.11/site-packages/drf_spectacular/drainage.py\", line 207, in wrapped_method\n    return method(self, request, *args, **kwargs)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/api/api/views/media_views.py\", line 147, in list\n    return self.get_media_results(request, params)\n           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/api/api/views/media_views.py\", line 200, in get_media_results\n    results = self.get_db_results(results)\n              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^\n  File \"/api/api/views/media_views.py\", line 126, in get_db_results\n    results = list(self.get_queryset().filter(identifier__in=identifiers))\n                   ^^^^^^^^^^^^^^^^^^^\n  File \"/api/api/views/image_views.py\", line 61, in get_queryset\n    return super().get_queryset().select_related(\"sensitive_image\")\n           ^^^^^^^^^^^^^^^^^^^^^^\n  File \"/api/api/views/media_views.py\", line 84, in get_queryset\n    raise ValueError(\"Whoa! That ain't right!!!\")\nValueError: Whoa! That ain't right!!!"}

Checklist

• My pull request has a descriptive title (not a vague title likeUpdate index.md).
• My pull request targets the default branch of the repository (main) or a parent feature branch.
• My commit messages follow best practices.
• My code follows the established code style of the repository.
• I added or updated tests for the changes I made (if applicable).
• I added or updated documentation (if applicable).
• I tried running the project locally and verified that there are no visible errors.
• [N/A] I ran the DAG documentation generator (just catalog/generate-docs for catalog
  PRs) or the media properties generator (just catalog/generate-docs media-props
  for the catalog or just api/generate-docs for the API) where applicable.

Developer Certificate of Origin

Developer Certificate of Origin

Developer Certificate of Origin
Version 1.1

Copyright (C) 2004, 2006 The Linux Foundation and its contributors.
1 Letterman Drive
Suite D4700
San Francisco, CA, 94129

Everyone is permitted to copy and distribute verbatim copies of this
license document, but changing it is not allowed.


Developer's Certificate of Origin 1.1

By making a contribution to this project, I certify that:

(a) The contribution was created in whole or in part by me and I
    have the right to submit it under the open source license
    indicated in the file; or

(b) The contribution is based upon previous work that, to the best
    of my knowledge, is covered under an appropriate open source
    license and I have the right under that license to submit that
    work with modifications, whether created in whole or in part
    by me, under the same open source license (unless I am
    permitted to submit under a different license), as indicated
    in the file; or

(c) The contribution was provided directly to me by some other
    person who certified (a), (b) or (c) and I have not modified
    it.

(d) I understand and agree that this project and the contribution
    are public and that a record of the contribution (including all
    personal information I submit with it, including my sign-off) is
    maintained indefinitely and may be redistributed consistent with
    this project or the open source license(s) involved.

[dhruvkb]

LGTM.

Just wanted to note here that uvicorn still writes some logs using the non-structured format.

[sarayourfriend]

Just wanted to note here that uvicorn still writes some logs using the non-structured format.

Those were the ones I mentioned that leak out of this. To fix that we'd need to move the logging configuration into run.py, I believe, so that it exists before uvicorn starts trying to log anything.

It only happens on task start though, so I think it'll be okay. The only ones that happen in production are the Elasticsearch connection one (which happens in api/run.sh) and uvicorn's "listening on ...". The two watcher logs never happen in production.

[zackkrida]

Great 👍