diff --git a/api/api/admin/media_report.py b/api/api/admin/media_report.py index cf5abc618a6..151c473cd1c 100644 --- a/api/api/admin/media_report.py +++ b/api/api/admin/media_report.py @@ -1,8 +1,7 @@ -import logging - from django.conf import settings from django.contrib import admin +import structlog from elasticsearch import NotFoundError from elasticsearch_dsl import Search from openverse_attribution.license import License @@ -10,6 +9,9 @@ from api.models import PENDING +logger = structlog.get_logger(__name__) + + class MediaReportAdmin(admin.ModelAdmin): change_form_template = "admin/api/media_report/change_form.html" list_display = ("id", "reason", "is_pending", "description", "created_at", "url") @@ -88,7 +90,7 @@ def has_sensitive_text(self, obj): if search.hits: return False except NotFoundError: - logging.error(f"Could not resolve index {filtered_index}") + logger.error(f"Could not resolve index {filtered_index}") return None return True @@ -118,7 +120,7 @@ def _get_media_obj_data(self, obj): "tags": tags_by_provider, "description": obj.media_obj.meta_data.get("description", ""), } - logging.info(f"Additional data: {additional_data}") + logger.info(f"Additional data: {additional_data}") return additional_data def change_view(self, request, object_id, form_url="", extra_context=None): diff --git a/api/api/controllers/elasticsearch/helpers.py b/api/api/controllers/elasticsearch/helpers.py index 808a7b81b29..11580192bd4 100644 --- a/api/api/controllers/elasticsearch/helpers.py +++ b/api/api/controllers/elasticsearch/helpers.py @@ -1,7 +1,6 @@ from __future__ import annotations import functools -import logging as log import pprint import time from itertools import accumulate @@ -9,12 +8,16 @@ from django.conf import settings +import structlog from elasticsearch import BadRequestError, NotFoundError from elasticsearch_dsl import Search from api.utils.dead_link_mask import get_query_hash, get_query_mask +logger = structlog.get_logger(__name__) + + def log_timing_info(func): @functools.wraps(func) def wrapper(*args, es_query, **kwargs): @@ -28,12 +31,12 @@ def wrapper(*args, es_query, **kwargs): es_time_in_ms = result.took else: es_time_in_ms = result.get("took") - log.info( - { - "response_time": response_time_in_ms, - "es_time": es_time_in_ms, - "es_query": es_query, - } + logger.info( + "Performed ES query", + func=func.__name__, + response_time=response_time_in_ms, + es_time=es_time_in_ms, + es_query=es_query, ) return result @@ -44,13 +47,13 @@ def wrapper(*args, es_query, **kwargs): @log_timing_info def get_es_response(s, *args, **kwargs): if settings.VERBOSE_ES_RESPONSE: - log.info(pprint.pprint(s.to_dict())) + logger.info(pprint.pprint(s.to_dict())) try: search_response = s.execute() if settings.VERBOSE_ES_RESPONSE: - log.info(pprint.pprint(search_response.to_dict())) + logger.info(pprint.pprint(search_response.to_dict())) except (BadRequestError, NotFoundError) as e: raise ValueError(e) diff --git a/api/api/controllers/search_controller.py b/api/api/controllers/search_controller.py index 2f322e75e96..c831375cd59 100644 --- a/api/api/controllers/search_controller.py +++ b/api/api/controllers/search_controller.py @@ -1,7 +1,5 @@ from __future__ import annotations -import logging -import logging as log import re from math import ceil from typing import TYPE_CHECKING @@ -9,6 +7,7 @@ from django.conf import settings from django.core.cache import cache +import structlog from decouple import config from elasticsearch.exceptions import NotFoundError from elasticsearch_dsl import Q, Search @@ -36,7 +35,7 @@ if TYPE_CHECKING: from api.serializers.media_serializers import MediaSearchRequestSerializer -module_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) NESTING_THRESHOLD = config("POST_PROCESS_NESTING_THRESHOLD", cast=int, default=5) @@ -91,16 +90,13 @@ def _post_process_results( :return: List of results. """ - logger = module_logger.getChild("_post_process_results") if nesting > NESTING_THRESHOLD: logger.info( - { - "message": "Nesting threshold breached", - "nesting": nesting, - "start": start, - "end": end, - "page_size": page_size, - } + "Nesting threshold breached", + nesting=nesting, + start=start, + end=end, + page_size=page_size, ) results = list(search_results) @@ -175,8 +171,6 @@ def get_excluded_providers_query() -> Q | None: `:FILTERED_PROVIDERS_CACHE_VERSION:FILTERED_PROVIDERS_CACHE_KEY` key. """ - logger = module_logger.getChild("get_excluded_providers_query") - try: filtered_providers = cache.get( key=FILTERED_PROVIDERS_CACHE_KEY, version=FILTERED_PROVIDERS_CACHE_VERSION @@ -362,7 +356,7 @@ def log_query_features(query: str, query_name) -> None: if bool(re.search(pattern, query)): query_flags.append(flag) if query_flags: - log.info( + logger.info( { "log_message": "Special features present in query", "query_name": query_name, @@ -560,11 +554,11 @@ def get_sources(index): except ValueError: cache_fetch_failed = True sources = None - log.warning("Source cache fetch failed due to corruption") + logger.warning("Source cache fetch failed due to corruption") except ConnectionError: cache_fetch_failed = True sources = None - log.warning("Redis connect failed, cannot get cached sources.") + logger.warning("Redis connect failed, cannot get cached sources.") if isinstance(sources, list) or cache_fetch_failed: sources = None @@ -572,7 +566,7 @@ def get_sources(index): # Invalidate old provider format. cache.delete(key=source_cache_name) except ConnectionError: - log.warning("Redis connect failed, cannot invalidate cached sources.") + logger.warning("Redis connect failed, cannot invalidate cached sources.") if not sources: # Don't increase `size` without reading this issue first: @@ -607,7 +601,7 @@ def get_sources(index): key=source_cache_name, timeout=SOURCE_CACHE_TIMEOUT, value=sources ) except ConnectionError: - log.warning("Redis connect failed, cannot cache sources.") + logger.warning("Redis connect failed, cannot cache sources.") sources = {source: int(doc_count) for source, doc_count in sources.items()} return sources diff --git a/api/api/management/commands/generatewaveforms.py b/api/api/management/commands/generatewaveforms.py index b75852b75e4..51d39afefd2 100644 --- a/api/api/management/commands/generatewaveforms.py +++ b/api/api/management/commands/generatewaveforms.py @@ -1,4 +1,3 @@ -import logging import subprocess from django_tqdm import BaseCommand @@ -86,10 +85,6 @@ def _process_wavelengths(self, audios, audio_handler, count_to_process): return errored_identifiers def handle(self, *args, **options): - # These logs really muck up the tqdm output and don't give us much helpful - # information, so they get silenced - logging.getLogger("api.utils.waveform").setLevel(logging.WARNING) - existing_waveform_audio_identifiers_query = AudioAddOn.objects.filter( waveform_peaks__isnull=False ).values_list("audio_identifier", flat=True) diff --git a/api/api/models/media.py b/api/api/models/media.py index b2fd53e0cf1..e175dcf3311 100644 --- a/api/api/models/media.py +++ b/api/api/models/media.py @@ -1,4 +1,3 @@ -import logging import mimetypes from django.conf import settings @@ -7,6 +6,7 @@ from django.urls import reverse from django.utils.html import format_html +import structlog from elasticsearch import Elasticsearch, NotFoundError from openverse_attribution.license import License @@ -24,7 +24,7 @@ DMCA = "dmca" OTHER = "other" -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) class AbstractMedia( @@ -314,7 +314,6 @@ def _perform_index_update(self, method: str, raise_errors: bool, **es_method_arg Automatically handles ``DoesNotExist`` warnings, forces a refresh, and calls the method for origin and filtered indexes. """ - logger = parent_logger.getChild("PerformIndexUpdateMixin._perform_index_update") es: Elasticsearch = settings.ES try: diff --git a/api/api/serializers/media_serializers.py b/api/api/serializers/media_serializers.py index 9ff56a29949..c3715d17498 100644 --- a/api/api/serializers/media_serializers.py +++ b/api/api/serializers/media_serializers.py @@ -1,4 +1,3 @@ -import logging from collections import namedtuple from typing import TypedDict @@ -36,8 +35,6 @@ from api.utils.url import add_protocol -logger = logging.getLogger(__name__) - ####################### # Request serializers # ####################### diff --git a/api/api/utils/aiohttp.py b/api/api/utils/aiohttp.py index 339f9db0bf6..bebe39c07a1 100644 --- a/api/api/utils/aiohttp.py +++ b/api/api/utils/aiohttp.py @@ -1,13 +1,13 @@ import asyncio -import logging import weakref import aiohttp import sentry_sdk +import structlog from django_asgi_lifespan.signals import asgi_shutdown -logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) _SESSIONS: weakref.WeakKeyDictionary[ diff --git a/api/api/utils/check_dead_links/__init__.py b/api/api/utils/check_dead_links/__init__.py index 219e60480a9..d21e89b9d4b 100644 --- a/api/api/utils/check_dead_links/__init__.py +++ b/api/api/utils/check_dead_links/__init__.py @@ -1,11 +1,11 @@ import asyncio -import logging import time from django.conf import settings import aiohttp import django_redis +import structlog from asgiref.sync import async_to_sync from decouple import config from elasticsearch_dsl.response import Hit @@ -16,7 +16,7 @@ from api.utils.dead_link_mask import get_query_mask, save_query_mask -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) CACHE_PREFIX = "valid:" @@ -32,7 +32,6 @@ def _get_cached_statuses(redis, image_urls): int(b.decode("utf-8")) if b is not None else None for b in cached_statuses ] except ConnectionError: - logger = parent_logger.getChild("_get_cached_statuses") logger.warning("Redis connect failed, validating all URLs without cache.") return [None] * len(image_urls) @@ -77,7 +76,6 @@ def check_dead_links( Results are cached in redis and shared amongst all API servers in the cluster. """ - logger = parent_logger.getChild("check_dead_links") if not image_urls: logger.info("no image urls to validate") return @@ -177,5 +175,4 @@ def check_dead_links( def _log_validation_failure(exception): - logger = parent_logger.getChild("_log_validation_failure") logger.warning(f"Failed to validate image! Reason: {exception}") diff --git a/api/api/utils/dead_link_mask.py b/api/api/utils/dead_link_mask.py index 1791daf1673..7a9e3e76531 100644 --- a/api/api/utils/dead_link_mask.py +++ b/api/api/utils/dead_link_mask.py @@ -1,12 +1,11 @@ -import logging - import django_redis +import structlog from deepdiff import DeepHash from elasticsearch_dsl import Search from redis.exceptions import ConnectionError -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) # 3 hours minutes (in seconds) @@ -43,7 +42,6 @@ def get_query_mask(query_hash: str) -> list[int]: try: return list(map(int, redis.lrange(key, 0, -1))) except ConnectionError: - logger = parent_logger.getChild("get_query_mask") logger.warning("Redis connect failed, cannot get cached query mask.") return [] @@ -65,5 +63,4 @@ def save_query_mask(query_hash: str, mask: list): try: redis_pipe.execute() except ConnectionError: - logger = parent_logger.getChild("save_query_mask") logger.warning("Redis connect failed, cannot cache query mask.") diff --git a/api/api/utils/image_proxy/__init__.py b/api/api/utils/image_proxy/__init__.py index 5f47c034b8e..8cac9613a96 100644 --- a/api/api/utils/image_proxy/__init__.py +++ b/api/api/utils/image_proxy/__init__.py @@ -1,4 +1,3 @@ -import logging from dataclasses import dataclass from datetime import timedelta from functools import wraps @@ -12,6 +11,7 @@ import aiohttp import django_redis +import structlog from aiohttp.client_exceptions import ClientResponseError from asgiref.sync import sync_to_async from redis.client import Redis @@ -24,7 +24,7 @@ from api.utils.tallies import get_monthly_timestamp -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) HEADERS = { "User-Agent": settings.OUTBOUND_USER_AGENT_TEMPLATE.format( @@ -96,8 +96,6 @@ def _tally_response( the `get` function, which is complex enough as is. """ - logger = parent_logger.getChild("_tally_response") - with tallies_conn.pipeline() as tallies: tallies.incr(f"thumbnail_response_code:{month}:{response.status}") tallies.incr( @@ -117,7 +115,6 @@ def _tally_response( @sync_to_async def _tally_client_response_errors(tallies, month: str, domain: str, status: int): - logger = parent_logger.getChild("_tally_client_response_errors") try: tallies.incr(f"thumbnail_http_error:{domain}:{month}:{status}") except ConnectionError: @@ -143,7 +140,6 @@ def _cache_repeated_failures(_get): while still allowing them to get temporarily cached as a failure if additional requests fail and push the counter over the threshold. """ - logger = parent_logger.getChild("_cache_repeated_failures") @wraps(_get) async def do_cache(*args, **kwargs): @@ -221,7 +217,6 @@ async def get( image_url = media_info.image_url media_identifier = media_info.media_identifier - logger = parent_logger.getChild("get") tallies = django_redis.get_redis_connection("tallies") tallies_incr = sync_to_async(tallies.incr) month = get_monthly_timestamp() diff --git a/api/api/utils/image_proxy/extension.py b/api/api/utils/image_proxy/extension.py index 2773b9d6a4e..5519dea4217 100644 --- a/api/api/utils/image_proxy/extension.py +++ b/api/api/utils/image_proxy/extension.py @@ -1,4 +1,3 @@ -import logging import mimetypes from os.path import splitext from urllib.parse import urlparse @@ -6,6 +5,7 @@ import aiohttp import django_redis import sentry_sdk +import structlog from asgiref.sync import sync_to_async from redis.exceptions import ConnectionError @@ -13,15 +13,13 @@ from api.utils.image_proxy.exception import UpstreamThumbnailException -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) _HEAD_TIMEOUT = aiohttp.ClientTimeout(10) async def get_image_extension(image_url: str, media_identifier) -> str | None: - logger = parent_logger.getChild("get_image_extension") - cache = django_redis.get_redis_connection("default") key = f"media:{media_identifier}:thumb_type" @@ -60,7 +58,6 @@ async def get_image_extension(image_url: str, media_identifier) -> str | None: @sync_to_async def _cache_extension(cache, key, ext): - logger = parent_logger.getChild("cache_extension") try: cache.set(key, ext if ext else "unknown") except ConnectionError: diff --git a/api/api/utils/tallies.py b/api/api/utils/tallies.py index 85710a38a70..4c21018947b 100644 --- a/api/api/utils/tallies.py +++ b/api/api/utils/tallies.py @@ -1,13 +1,13 @@ -import logging from collections import defaultdict from datetime import datetime, timedelta import django_redis +import structlog from django_redis.client.default import Redis from redis.exceptions import ConnectionError -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) def get_weekly_timestamp() -> str: @@ -45,5 +45,4 @@ def count_provider_occurrences(results: list[dict], index: str) -> None: try: pipe.execute() except ConnectionError: - logger = parent_logger.getChild("count_provider_occurrences") logger.warning("Redis connect failed, cannot increment provider tallies.") diff --git a/api/api/utils/throttle.py b/api/api/utils/throttle.py index 8d4f4b1a859..e4de75f2c9c 100644 --- a/api/api/utils/throttle.py +++ b/api/api/utils/throttle.py @@ -1,12 +1,12 @@ import abc -import logging from rest_framework.throttling import SimpleRateThrottle as BaseSimpleRateThrottle +import structlog from redis.exceptions import ConnectionError -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) class SimpleRateThrottle(BaseSimpleRateThrottle, metaclass=abc.ABCMeta): @@ -19,7 +19,6 @@ def allow_request(self, request, view): try: is_allowed = super().allow_request(request, view) except ConnectionError: - logger = parent_logger.getChild("allow_request") logger.warning("Redis connect failed, allowing request.") is_allowed = True view.headers |= self.headers() diff --git a/api/api/utils/watermark.py b/api/api/utils/watermark.py index 764a0a69ada..7a77a2be0f8 100644 --- a/api/api/utils/watermark.py +++ b/api/api/utils/watermark.py @@ -1,4 +1,3 @@ -import logging import os from enum import Flag, auto from io import BytesIO @@ -9,12 +8,13 @@ from rest_framework.exceptions import APIException import requests +import structlog from openverse_attribution.license import License from PIL import Image, ImageDraw, ImageFont, UnidentifiedImageError from sentry_sdk import capture_exception -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) BREAKPOINT_DIMENSION = 400 # 400px @@ -147,7 +147,6 @@ def _open_image(url): :param url: the URL from where to read the image :return: the PIL image object with the EXIF data """ - logger = parent_logger.getChild("_open_image") try: response = requests.get(url, headers=HEADERS) response.raise_for_status() diff --git a/api/api/utils/waveform.py b/api/api/utils/waveform.py index 22e13f7aa03..44c90237eae 100644 --- a/api/api/utils/waveform.py +++ b/api/api/utils/waveform.py @@ -1,5 +1,4 @@ import json -import logging import math import mimetypes import os @@ -10,9 +9,10 @@ from django.conf import settings import requests +import structlog -parent_logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) TMP_DIR = pathlib.Path("/tmp").resolve() UA_STRING = settings.OUTBOUND_USER_AGENT_TEMPLATE.format(purpose="Waveform") @@ -45,7 +45,6 @@ def download_audio(url, identifier): :returns: the name of the file on the disk """ - logger = parent_logger.getChild("download_audio") logger.info(f"downloading file url={url}") headers = {"User-Agent": UA_STRING} @@ -74,7 +73,6 @@ def generate_waveform(file_name, duration): :param duration: the duration of the audio to determine pixels per second """ - logger = parent_logger.getChild("generate_waveform") logger.info("Invoking audiowaveform") pps = math.ceil(1e6 / duration) # approx 1000 points in total @@ -105,7 +103,6 @@ def process_waveform_output(json_out): :returns: the list of peaks """ - logger = parent_logger.getChild("process_waveform_output") logger.info("Transforming points") output = json.loads(json_out) @@ -136,8 +133,6 @@ def cleanup(file_name): :param file_name: the name of the file to delete """ - logger = parent_logger.getChild("cleanup") - file_path = TMP_DIR.joinpath(file_name) logger.debug(f"file_path={file_path}") if file_path.exists(): diff --git a/api/api/views/media_views.py b/api/api/views/media_views.py index 1018ef94c78..54839fbeaba 100644 --- a/api/api/views/media_views.py +++ b/api/api/views/media_views.py @@ -1,4 +1,3 @@ -import logging from typing import Union from rest_framework import status @@ -7,6 +6,7 @@ from rest_framework.response import Response from rest_framework.viewsets import ReadOnlyModelViewSet +import structlog from adrf.views import APIView as AsyncAPIView from adrf.viewsets import ViewSetMixin as AsyncViewSetMixin from asgiref.sync import sync_to_async @@ -28,7 +28,7 @@ ) -logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) MediaListRequestSerializer = Union[ media_serializers.PaginatedRequestSerializer, diff --git a/api/api/views/oauth2_views.py b/api/api/views/oauth2_views.py index 45f717c3139..be29390cb3f 100644 --- a/api/api/views/oauth2_views.py +++ b/api/api/views/oauth2_views.py @@ -1,5 +1,4 @@ import json -import logging as log import secrets import smtplib from textwrap import dedent @@ -14,6 +13,7 @@ from rest_framework.reverse import reverse from rest_framework.views import APIView +import structlog from drf_spectacular.utils import extend_schema from oauth2_provider.contrib.rest_framework.permissions import TokenHasScope from oauth2_provider.generators import generate_client_secret @@ -29,7 +29,7 @@ from api.utils.throttle import OnePerSecond, TenPerDay -module_logger = log.getLogger(__name__) +logger = structlog.get_logger(__name__) class InvalidCredentials(APIException): @@ -109,8 +109,8 @@ def post(self, request, format=None): fail_silently=False, ) except smtplib.SMTPException as e: - log.error("Failed to send API verification email!") - log.error(e) + logger.error("Failed to send API verification email!") + logger.error(e) # Give the user their newly created credentials. return Response( status=201, @@ -236,7 +236,6 @@ def get(self, request: Request, format=None): burst_requests = len(burst_requests_list) if burst_requests_list else None status = 200 except ConnectionError: - logger = module_logger.getChild("CheckRates.get") logger.warning("Redis connect failed, cannot get key usage.") burst_requests = None sustained_requests = None diff --git a/api/conf/settings/__init__.py b/api/conf/settings/__init__.py index 9efb1fbadde..f52fd936035 100644 --- a/api/conf/settings/__init__.py +++ b/api/conf/settings/__init__.py @@ -27,6 +27,7 @@ "security.py", "auth.py", "logging.py", + "signals.py", "i18n.py", "static.py", # services diff --git a/api/conf/settings/link_validation_cache.py b/api/conf/settings/link_validation_cache.py index 4fb72164c92..c872c220b1b 100644 --- a/api/conf/settings/link_validation_cache.py +++ b/api/conf/settings/link_validation_cache.py @@ -1,15 +1,15 @@ import json -import logging import os from collections import defaultdict from datetime import timedelta from django.core.exceptions import ImproperlyConfigured +import structlog from decouple import config -logger = logging.getLogger(__name__) +logger = structlog.get_logger(__name__) class LinkValidationCacheExpiryConfiguration(defaultdict): diff --git a/api/conf/settings/logging.py b/api/conf/settings/logging.py index a8ae2a842cb..a1fa51bb28d 100644 --- a/api/conf/settings/logging.py +++ b/api/conf/settings/logging.py @@ -1,8 +1,9 @@ from logging import LogRecord +import structlog from decouple import config -from conf.settings.base import MIDDLEWARE +from conf.settings.base import ENVIRONMENT, INSTALLED_APPS, MIDDLEWARE from conf.settings.security import DEBUG @@ -11,8 +12,18 @@ def health_check_filter(record: LogRecord) -> bool: return not ("GET /healthcheck" in record.getMessage() and record.status_code == 200) +# https://django-structlog.readthedocs.io/en/latest/getting_started.html#installation +if "django_structlog" not in INSTALLED_APPS: + INSTALLED_APPS.append("django_structlog") + +MIDDLEWARE.insert(0, "django_structlog.middlewares.RequestMiddleware") + LOG_LEVEL = config("LOG_LEVEL", default="INFO").upper() DJANGO_DB_LOGGING = config("DJANGO_DB_LOGGING", cast=bool, default=False) +LOG_PROCESSOR = config( + "LOG_PROCESSOR", + default="console" if ENVIRONMENT == "local" else "json", +) # Set to a pipe-delimited string of gc debugging flags # https://docs.python.org/3/library/gc.html#gc.DEBUG_STATS @@ -20,21 +31,12 @@ def health_check_filter(record: LogRecord) -> bool: "GC_DEBUG_LOGGING", cast=lambda x: x.split("|") if x else [], default="" ) -# https://github.com/dabapps/django-log-request-id#logging-all-requests -LOG_REQUESTS = True - -# https://github.com/dabapps/django-log-request-id -MIDDLEWARE.insert(0, "log_request_id.middleware.RequestIDMiddleware") -# https://github.com/dabapps/django-log-request-id#installation-and-usage -REQUEST_ID_RESPONSE_HEADER = "X-Request-Id" - # Logging configuration LOGGING = { # NOTE: Most of this is inherited from the default configuration "version": 1, "disable_existing_loggers": False, "filters": { - "request_id": {"()": "log_request_id.filters.RequestIDFilter"}, "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"}, "require_debug_true": {"()": "django.utils.log.RequireDebugTrue"}, "health_check": { @@ -43,81 +45,94 @@ def health_check_filter(record: LogRecord) -> bool: }, }, "formatters": { - "django.server": { - "()": "django.utils.log.ServerFormatter", - "format": "[{server_time}] {message}", + "console": { + "format": "[{asctime} - {name} - {lineno:>3}][{levelname}] {message}", "style": "{", }, - "console": { - "format": "[%(asctime)s - %(name)s - %(lineno)3d][%(levelname)s] [%(request_id)s] %(message)s", # noqa: E501 + "structured": { + "()": structlog.stdlib.ProcessorFormatter, + "processor": structlog.processors.JSONRenderer() + if LOG_PROCESSOR == "json" + else structlog.dev.ConsoleRenderer(), }, }, "handlers": { # Default console logger "console": { "level": LOG_LEVEL, - "filters": ["require_debug_true", "request_id"], "class": "logging.StreamHandler", "formatter": "console", }, - # Add a clause to log error messages to the console in production - "console_prod": { + "console_structured": { "level": LOG_LEVEL, - "filters": ["require_debug_false", "request_id"], "class": "logging.StreamHandler", - "formatter": "console", + "formatter": "structured", }, - # Handler for all other logging - "general_console": { + }, + "loggers": { + # Application + "django_structlog": { + "handlers": ["console_structured"], "level": LOG_LEVEL, - "filters": ["request_id"], - "class": "logging.StreamHandler", - "formatter": "console", + "propagate": False, }, - # Default server logger - "django.server": { + "api": { + "handlers": ["console_structured"], "level": LOG_LEVEL, - "filters": ["request_id"], - "class": "logging.StreamHandler", - "formatter": "django.server", - }, - # Default mailing logger - "mail_admins": { - "level": "ERROR", - "filters": ["request_id", "require_debug_false"], - "class": "django.utils.log.AdminEmailHandler", + "propagate": False, }, - }, - "loggers": { + # External "django": { - "handlers": ["console", "console_prod", "mail_admins"], + "handlers": ["console"], # Keep this at info to avoid django internal debug logs; # we just want our own debug logs when log level is set to debug "level": "INFO", "propagate": False, }, - "django.server": { - "handlers": ["django.server"], - # Filter health check logs - "filters": ["health_check", "request_id"], + "uvicorn.error": { # Using just "uvicorn" will re-enable access logs + "handlers": ["console"], "level": LOG_LEVEL, "propagate": False, }, # Default handler for all other loggers "": { - "handlers": ["general_console"], - "filters": ["request_id"], + "handlers": ["console"], "level": LOG_LEVEL, }, }, } +# https://django-structlog.readthedocs.io/en/latest/getting_started.html +structlog.configure( + processors=[ + structlog.contextvars.merge_contextvars, + structlog.stdlib.filter_by_level, + structlog.processors.TimeStamper(fmt="iso"), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.CallsiteParameterAdder( + { + structlog.processors.CallsiteParameter.FILENAME, + structlog.processors.CallsiteParameter.FUNC_NAME, + structlog.processors.CallsiteParameter.LINENO, + } + ), + structlog.processors.StackInfoRenderer(), + structlog.processors.format_exc_info, + structlog.processors.UnicodeDecoder(), + structlog.stdlib.ProcessorFormatter.wrap_for_formatter, + ], + logger_factory=structlog.stdlib.LoggerFactory(), + cache_logger_on_first_use=(ENVIRONMENT == "production"), +) + if DJANGO_DB_LOGGING: # Behind a separate flag as it's a very noisy debug logger # and it's nice to be able to enable it conditionally within that context LOGGING["loggers"]["django.db.backends"] = { "level": "DEBUG", - "handlers": ["console", "console_prod"], + "handlers": ["console"], "propagate": False, } diff --git a/api/conf/settings/signals.py b/api/conf/settings/signals.py new file mode 100644 index 00000000000..3e59b6fb53a --- /dev/null +++ b/api/conf/settings/signals.py @@ -0,0 +1,12 @@ +from django.dispatch import receiver + +import structlog +from django_structlog import signals + + +# https://django-structlog.readthedocs.io/en/latest/how_tos.html#bind-request-id-to-response-s-header +@receiver(signals.update_failure_response) +@receiver(signals.bind_extra_request_finished_metadata) +def add_request_id_to_error_response(response, logger, **kwargs): + context = structlog.contextvars.get_merged_contextvars(logger) + response["X-Request-ID"] = context["request_id"] diff --git a/api/pdm.lock b/api/pdm.lock index 71ec5fc29d5..6d3a6233d4e 100644 --- a/api/pdm.lock +++ b/api/pdm.lock @@ -5,7 +5,7 @@ groups = ["default", "dev", "overrides", "test"] strategy = ["cross_platform", "inherit_metadata"] lock_version = "4.4.1" -content_hash = "sha256:c489a98705c98c79da029deab97b14edd4fe69f3d23ea3f0f4b1641c052776a7" +content_hash = "sha256:7e9f8e52e78990958b094effb69b7b3500def794137e4d75c5d05de015bb99d4" [[package]] name = "adrf" @@ -413,16 +413,17 @@ files = [ ] [[package]] -name = "django-log-request-id" -version = "2.1.0" -summary = "Django middleware and log filter to attach a unique ID to every log message generated as part of a request" +name = "django-ipware" +version = "7.0.1" +requires_python = ">=3.8" +summary = "A Django application to retrieve user's IP address" groups = ["default"] dependencies = [ - "django>=1.8", + "python-ipware>=2.0.3", ] files = [ - {file = "django-log-request-id-2.1.0.tar.gz", hash = "sha256:b11fc821774b54b820ef2e732dbaa52304711de8d5c4f9031ca48578f6121ab6"}, - {file = "django_log_request_id-2.1.0-py3-none-any.whl", hash = "sha256:c0793c030cfe9f673eff3f89667711f65c39509c016d85e436f9d48507ee778c"}, + {file = "django-ipware-7.0.1.tar.gz", hash = "sha256:d9ec43d2bf7cdf216fed8d494a084deb5761a54860a53b2e74346a4f384cff47"}, + {file = "django_ipware-7.0.1-py2.py3-none-any.whl", hash = "sha256:db16bbee920f661ae7f678e4270460c85850f03c6761a4eaeb489bdc91f64709"}, ] [[package]] @@ -480,6 +481,23 @@ files = [ {file = "django_split_settings-1.3.1.tar.gz", hash = "sha256:c1f57f6b54fc0d93082c12163e76fad082c214f5fa0d16d84a1226d2c9f14f26"}, ] +[[package]] +name = "django-structlog" +version = "8.0.0" +requires_python = ">=3.8" +summary = "Structured Logging for Django" +groups = ["default"] +dependencies = [ + "asgiref>=3.6.0", + "django-ipware>=6.0.2", + "django>=3.2", + "structlog>=21.4.0", +] +files = [ + {file = "django-structlog-8.0.0.tar.gz", hash = "sha256:e439ae173d8d852b5f991ff7528d8ce5b0ae003cc6ea513215334b3204aee09c"}, + {file = "django_structlog-8.0.0-py3-none-any.whl", hash = "sha256:8431db72e9093850f4ec952a74768619667ff43987e1559526de39a82e5869a7"}, +] + [[package]] name = "django-tqdm" version = "1.3.1" @@ -1455,6 +1473,17 @@ files = [ {file = "python_dotenv-1.0.1-py3-none-any.whl", hash = "sha256:f7b63ef50f1b690dddf550d03497b66d609393b40b564ed0d674909a68ebf16a"}, ] +[[package]] +name = "python-ipware" +version = "3.0.0" +requires_python = ">=3.7" +summary = "A Python package to retrieve user's IP address" +groups = ["default"] +files = [ + {file = "python_ipware-3.0.0-py3-none-any.whl", hash = "sha256:fc936e6e7ec9fcc107f9315df40658f468ac72f739482a707181742882e36b60"}, + {file = "python_ipware-3.0.0.tar.gz", hash = "sha256:9117b1c4dddcb5d5ca49e6a9617de2fc66aec2ef35394563ac4eecabdf58c062"}, +] + [[package]] name = "python-slugify" version = "8.0.4" @@ -1807,6 +1836,17 @@ files = [ {file = "starlette_testclient-0.3.0.tar.gz", hash = "sha256:31c28c10abd240beb327ef1ee4dc395403c87da07d4665126b7d3c7b60444e04"}, ] +[[package]] +name = "structlog" +version = "24.1.0" +requires_python = ">=3.8" +summary = "Structured Logging for Python" +groups = ["default"] +files = [ + {file = "structlog-24.1.0-py3-none-any.whl", hash = "sha256:3f6efe7d25fab6e86f277713c218044669906537bb717c1807a09d46bca0714d"}, + {file = "structlog-24.1.0.tar.gz", hash = "sha256:41a09886e4d55df25bdcb9b5c9674bccfab723ff43e0a86a1b7b236be8e57b16"}, +] + [[package]] name = "tabulate" version = "0.9.0" diff --git a/api/pyproject.toml b/api/pyproject.toml index 81f8ef101b1..708eedb0710 100644 --- a/api/pyproject.toml +++ b/api/pyproject.toml @@ -17,11 +17,11 @@ dependencies = [ "django >=4.2.11, <5", "django-asgi-lifespan >=0.3.1, <0.4", "django-cors-headers >=4.3.1, <5", - "django-log-request-id >=2.1.0, <3", "django-migrations-git-conflicts >=1.0, <2", "django-oauth-toolkit >=2.3.0, <3", "django-redis >=5.4.0, <6", "django-split-settings >=1.2.0, <2", + "django-structlog >=8.0.0, <9", "django-tqdm >=1.3.1, <2", "django-uuslug >=2.0.0, <3", "djangorestframework >=3.14.0, <4", diff --git a/api/run.py b/api/run.py index 5af1bf5696b..0265ad68092 100644 --- a/api/run.py +++ b/api/run.py @@ -19,13 +19,5 @@ "../packages/python/", ], log_level="debug", - log_config={ - "version": 1, - "formatters": { - "generic": { - "format": "[%(asctime)s - %(name)s - %(lineno)3d][%(levelname)s] %(message)s", # noqa: E501 - }, - }, - }, access_log=False, ) diff --git a/api/test/unit/controllers/test_search_controller.py b/api/test/unit/controllers/test_search_controller.py index 66bf55caf78..c25107adefe 100644 --- a/api/test/unit/controllers/test_search_controller.py +++ b/api/test/unit/controllers/test_search_controller.py @@ -1,5 +1,4 @@ import datetime -import logging import random import re from collections.abc import Callable @@ -13,6 +12,7 @@ from django_redis import get_redis_connection from elasticsearch_dsl import Search from elasticsearch_dsl.query import Terms +from structlog.testing import capture_logs from api.controllers import search_controller from api.controllers.elasticsearch import helpers as es_helpers @@ -820,7 +820,7 @@ def _delete_all_results_but_first(_, __, results, ___): ) serializer.is_valid() - with caplog.at_level(logging.INFO): + with capture_logs() as cap_logs: results, _, _, _ = search_controller.query_media( search_params=serializer, ip=0, @@ -830,7 +830,8 @@ def _delete_all_results_but_first(_, __, results, ___): page_size=2, filter_dead=True, ) - assert "Nesting threshold breached" in caplog.text + messages = [record["event"] for record in cap_logs] + assert "Nesting threshold breached" in messages @pytest.mark.django_db @@ -840,7 +841,7 @@ def _delete_all_results_but_first(_, __, results, ___): [(2, Terms(provider=["provider1", "provider2"])), (0, None)], ) def test_get_excluded_providers_query_returns_excluded( - excluded_count, result, is_cache_reachable, cache_name, request, caplog + excluded_count, result, is_cache_reachable, cache_name, request ): cache = request.getfixturevalue(cache_name) @@ -860,11 +861,13 @@ def test_get_excluded_providers_query_returns_excluded( filter_content=True, ) - assert search_controller.get_excluded_providers_query() == result + with capture_logs() as cap_logs: + assert search_controller.get_excluded_providers_query() == result if not is_cache_reachable: + messages = [record["event"] for record in cap_logs] assert all( - message in caplog.text + message in messages for message in [ "Redis connect failed, cannot get cached filtered providers.", "Redis connect failed, cannot cache filtered providers.", @@ -881,7 +884,7 @@ def test_get_sources_returns_stats(is_cache_reachable, cache_name, request, capl "sources-multimedia", value={"provider_1": "1000", "provider_2": "1000"} ) - with patch( + with capture_logs() as cap_logs, patch( "api.controllers.search_controller.get_raw_es_response", return_value={ "aggregations": { @@ -900,8 +903,9 @@ def test_get_sources_returns_stats(is_cache_reachable, cache_name, request, capl } if not is_cache_reachable: + messages = [record["event"] for record in cap_logs] assert all( - message in caplog.text + message in messages for message in [ "Redis connect failed, cannot get cached sources.", "Redis connect failed, cannot cache sources.", diff --git a/api/test/unit/utils/test_check_dead_links.py b/api/test/unit/utils/test_check_dead_links.py index 21eceb46781..2c99238d35d 100644 --- a/api/test/unit/utils/test_check_dead_links.py +++ b/api/test/unit/utils/test_check_dead_links.py @@ -3,6 +3,7 @@ import pook import pytest from aiohttp.client import ClientSession +from structlog.testing import capture_logs from api.utils.check_dead_links import HEADERS, check_dead_links @@ -87,7 +88,7 @@ def test_403_considered_dead(provider): "is_cache_reachable, cache_name", [(True, "redis"), (False, "unreachable_redis")], ) -def test_mset_and_expire_for_responses(is_cache_reachable, cache_name, request, caplog): +def test_mset_and_expire_for_responses(is_cache_reachable, cache_name, request): cache = request.getfixturevalue(cache_name) query_hash = "test_mset_and_expiry_for_responses" @@ -102,7 +103,8 @@ def test_mset_and_expire_for_responses(is_cache_reachable, cache_name, request, .reply(200) ) - check_dead_links(query_hash, start_slice, results, image_urls) + with capture_logs() as cap_logs: + check_dead_links(query_hash, start_slice, results, image_urls) if is_cache_reachable: for i in range(len(results)): @@ -110,8 +112,9 @@ def test_mset_and_expire_for_responses(is_cache_reachable, cache_name, request, # TTL is 30 days for 2xx responses assert cache.ttl(f"valid:https://example.org/{i}") == 2592000 else: + messages = [record["event"] for record in cap_logs] assert all( - message in caplog.text + message in messages for message in [ "Redis connect failed, validating all URLs without cache.", "Redis connect failed, cannot cache link liveness.", diff --git a/api/test/unit/utils/test_image_proxy.py b/api/test/unit/utils/test_image_proxy.py index bf364746e6b..246468e9e96 100644 --- a/api/test/unit/utils/test_image_proxy.py +++ b/api/test/unit/utils/test_image_proxy.py @@ -11,6 +11,7 @@ from aiohttp import client_exceptions from aiohttp.client_reqrep import ConnectionKey from asgiref.sync import async_to_sync +from structlog.testing import capture_logs from api.utils.image_proxy import ( FAILURE_CACHE_KEY_TEMPLATE, @@ -267,7 +268,7 @@ async def raise_exc(*args, **kwargs): @pytest.mark.pook @cache_availability_params def test_get_successful_records_response_code( - mock_image_data, is_cache_reachable, cache_name, request, caplog + mock_image_data, is_cache_reachable, cache_name, request ): cache = request.getfixturevalue(cache_name) ( @@ -284,7 +285,8 @@ def test_get_successful_records_response_code( .body(MOCK_BODY) ) - photon_get(TEST_MEDIA_INFO) + with capture_logs() as cap_logs: + photon_get(TEST_MEDIA_INFO) month = get_monthly_timestamp() keys = [ @@ -295,9 +297,8 @@ def test_get_successful_records_response_code( for key in keys: assert cache.get(key) == b"1" else: - assert ( - "Redis connect failed, thumbnail response codes not tallied." in caplog.text - ) + messages = [record["event"] for record in cap_logs] + assert "Redis connect failed, thumbnail response codes not tallied." in messages alert_count_params = pytest.mark.parametrize( @@ -349,7 +350,6 @@ def test_get_exception_handles_error( is_cache_reachable, cache_name, request, - caplog, ): cache = request.getfixturevalue(cache_name) @@ -359,7 +359,7 @@ def test_get_exception_handles_error( if is_cache_reachable: cache.set(key, count_start) - with pytest.raises(UpstreamThumbnailException): + with capture_logs() as cap_logs, pytest.raises(UpstreamThumbnailException): photon_get(TEST_MEDIA_INFO) sentry_capture_exception.assert_not_called() @@ -367,7 +367,8 @@ def test_get_exception_handles_error( if is_cache_reachable: assert cache.get(key) == str(count_start + 1).encode() else: - assert "Redis connect failed, thumbnail errors not tallied." in caplog.text + messages = [record["event"] for record in cap_logs] + assert "Redis connect failed, thumbnail errors not tallied." in messages @cache_availability_params @@ -390,7 +391,6 @@ def test_get_http_exception_handles_error( is_cache_reachable, cache_name, request, - caplog, ): cache = request.getfixturevalue(cache_name) @@ -399,7 +399,7 @@ def test_get_http_exception_handles_error( if is_cache_reachable: cache.set(key, count_start) - with pytest.raises(UpstreamThumbnailException): + with capture_logs() as cap_logs, pytest.raises(UpstreamThumbnailException): pook.get(PHOTON_URL_FOR_TEST_IMAGE).reply(status_code, text) photon_get(TEST_MEDIA_INFO) @@ -412,8 +412,9 @@ def test_get_http_exception_handles_error( == b"1" ) else: + messages = [record["event"] for record in cap_logs] assert all( - message in caplog.text + message in messages for message in [ "Redis connect failed, thumbnail HTTP errors not tallied.", "Redis connect failed, thumbnail errors not tallied.", @@ -612,7 +613,6 @@ def test_photon_get_saves_image_type_to_cache( is_cache_reachable, cache_name, request, - caplog, ): cache = request.getfixturevalue(cache_name) @@ -625,15 +625,16 @@ def test_photon_get_saves_image_type_to_cache( ) pook.on() pook.head(image_url, reply=200, response_headers=headers) - with pytest.raises(UnsupportedMediaType): + with capture_logs() as cap_logs, pytest.raises(UnsupportedMediaType): photon_get(media_info) key = f"media:{image.identifier}:thumb_type" if is_cache_reachable: assert cache.get(key) == expected_cache_val else: + messages = [record["event"] for record in cap_logs] assert all( - message in caplog.text + message in messages for message in [ "Redis connect failed, cannot get cached image extension.", "Redis connect failed, cannot cache image extension.", diff --git a/api/test/unit/utils/test_tallies.py b/api/test/unit/utils/test_tallies.py index 41fad62eb24..7b1aca54002 100644 --- a/api/test/unit/utils/test_tallies.py +++ b/api/test/unit/utils/test_tallies.py @@ -2,6 +2,7 @@ import pytest from freezegun import freeze_time +from structlog.testing import capture_logs from api.utils import tallies @@ -113,7 +114,7 @@ def test_count_provider_occurrences_increments_existing_tallies(redis): ) -def test_writes_error_logs_for_redis_connection_errors(unreachable_redis, caplog): +def test_writes_error_logs_for_redis_connection_errors(unreachable_redis): provider_counts = {"flickr": 4, "stocksnap": 6} results = [ @@ -122,7 +123,8 @@ def test_writes_error_logs_for_redis_connection_errors(unreachable_redis, caplog for _ in range(count) ] now = datetime(2023, 1, 19) # 16th is start of week - with freeze_time(now): + with capture_logs() as cap_logs, freeze_time(now): tallies.count_provider_occurrences(results, FAKE_MEDIA_TYPE) - assert "Redis connect failed, cannot increment provider tallies." in caplog.text + messages = [record["event"] for record in cap_logs] + assert "Redis connect failed, cannot increment provider tallies." in messages diff --git a/documentation/general/logging.md b/documentation/general/logging.md index c3f46e710c3..ca95a99aac7 100644 --- a/documentation/general/logging.md +++ b/documentation/general/logging.md @@ -1,39 +1,42 @@ # Logging -Openverse is in the process of establishing and implementing its logging -strategy. Until the -[introduction of more extensive logging in the Elasticsearch controller modules](https://github.com/WordPress/openverse-api/pull/790) -we did not have an established approach to logging. That PR still does not -establish a comprehensive approach, but it does introduce and follow some rules: - -1. Always use a child logger based on the module name and method name. For - example, at the top level of a module, there should be a `parent_logger` - variable that is the result of calling `logging.getLogger(__name__)`. - Individual methods that log should - [get a child logger for themselves based on this parent logger and their method name](https://docs.python.org/3/library/logging.html#logging.Logger.getChild): - -```py -def apply_filters(self, ...): - logging = parent_logger.getChild("apply_filters") - ... +Openverse uses structured logging for the API. + +## Best practices + +We follow these guidelines when writing logs from the API. + +1. Always declare the logger at the module level. This should ideally always be + the same statement: + + ```python + import structlog + logger = structlog.get_logger(__name__) + ``` + + Consistently use the variable name `logger`, invoke `structlog.get_logger` + (not `structlog.getLogger`) and supply `__name__` as the argument. + +2. There is no need to define child loggers because structured logs will always + include the `filename`, `funcname` and `lineno` fields. + +3. When logging multiple fields, you can include them as keyword arguments to + the logger. There is no need to serialize them or dump them as JSON. This + allows `structlog` to automatically render them as appropriate. + + ```python + logger.info("Event name", key_one=value_one, key_two=value_two) + ``` + +Thanks to structured logging and uniform practices, our logs will be uniformly +searchable and filterable. For example, to see all the logs for a method and +only that method, one can pipe the logs through `grep` like so. + +```bash +just logs web | grep 'func_name=' ``` -2. When logging variable values, log them in the following format: `name=value`. - Prefer that `name` equals the expression that produces the `value`. For - example, if logging the length of a list named `providers`, `name` should be - `len(providers)`, with the full expression looking like this: - `len(providers)={len(providers)}`. If logging a property of an object, prefer - `object.property_name={object.property_name}`. Exclude serialization from the - name like `json.dumps` as this is assumed: `verified={json.dumps(verified)}`. -3. Avoid using the `pprint` module for serializing log data as it significantly - increases the amount of space and time it takes to write a log. Instead, - prefer a simpler `json.dumps`. - -These practices provide context in the logs and makes them uniformly searchable -and filterable based on the values assigned to the names. Using a child logger -means we can easily see all the logs for a method. Using the `name=value` format -means we always know how to filter any given logged variable either by name or -by name and value. +## Request IDs Openverse also makes use of request IDs. Because multiple workers are writing to the same log at once, any given request's logs may be interspersed with the logs @@ -42,9 +45,12 @@ of a single request. This allows us to trace problematic requests through the codebase and understand what specific parts of the code are causing problems with these particular requests. +```bash +just logs web | grep 'request_id=' +``` + ## Future improvements Potential future improvements to logging in Openverse could include: -1. Structured logging format like formatting all logs as JSON. -2. Establishing clearer practices around what log levels to use and when. +1. Establishing clearer practices around what log levels to use and when.