Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add structured logging for the API #4263

Merged
merged 16 commits into from
May 7, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 6 additions & 4 deletions api/api/admin/media_report.py
Original file line number Diff line number Diff line change
@@ -1,15 +1,17 @@
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

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")
Expand Down Expand Up @@ -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

Expand Down Expand Up @@ -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):
Expand Down
21 changes: 12 additions & 9 deletions api/api/controllers/elasticsearch/helpers.py
Original file line number Diff line number Diff line change
@@ -1,20 +1,23 @@
from __future__ import annotations

import functools
import logging as log
import pprint
import time
from itertools import accumulate
from math import ceil

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):
Expand All @@ -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
Expand All @@ -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)

Expand Down
30 changes: 12 additions & 18 deletions api/api/controllers/search_controller.py
Original file line number Diff line number Diff line change
@@ -1,14 +1,13 @@
from __future__ import annotations

import logging
import logging as log
import re
from math import ceil
from typing import TYPE_CHECKING

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
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -560,19 +554,19 @@ 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.")
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if it would be nice to change these to structured logs too, maybe in a future issue. Something like logger.warning("Redis connect failed", when="get-cached-sources"), and so forth. Ideally these logs never matter though, and would never be meaningful to query, so probably not worth it!

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, we should definitely update existing logs to be more "structured" but that, like you said, will have to be a separate issue and PR.


if isinstance(sources, list) or cache_fetch_failed:
sources = None
try:
# 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:
Expand Down Expand Up @@ -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
Expand Down
5 changes: 0 additions & 5 deletions api/api/management/commands/generatewaveforms.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import logging
import subprocess

from django_tqdm import BaseCommand
Expand Down Expand Up @@ -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)
Expand Down
5 changes: 2 additions & 3 deletions api/api/models/media.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import logging
import mimetypes

from django.conf import settings
Expand All @@ -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

Expand All @@ -24,7 +24,7 @@
DMCA = "dmca"
OTHER = "other"

parent_logger = logging.getLogger(__name__)
logger = structlog.get_logger(__name__)


class AbstractMedia(
Expand Down Expand Up @@ -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:
Expand Down
3 changes: 0 additions & 3 deletions api/api/serializers/media_serializers.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import logging
from collections import namedtuple
from typing import TypedDict

Expand Down Expand Up @@ -36,8 +35,6 @@
from api.utils.url import add_protocol


logger = logging.getLogger(__name__)

#######################
# Request serializers #
#######################
Expand Down
4 changes: 2 additions & 2 deletions api/api/utils/aiohttp.py
Original file line number Diff line number Diff line change
@@ -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[
Expand Down
7 changes: 2 additions & 5 deletions api/api/utils/check_dead_links/__init__.py
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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:"
Expand All @@ -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)

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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}")
7 changes: 2 additions & 5 deletions api/api/utils/dead_link_mask.py
Original file line number Diff line number Diff line change
@@ -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)
Expand Down Expand Up @@ -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 []

Expand All @@ -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.")
9 changes: 2 additions & 7 deletions api/api/utils/image_proxy/__init__.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import logging
from dataclasses import dataclass
from datetime import timedelta
from functools import wraps
Expand All @@ -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
Expand All @@ -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(
Expand Down Expand Up @@ -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(
Expand All @@ -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:
Expand All @@ -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):
Expand Down Expand Up @@ -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()
Expand Down
Loading
Loading