From 111083984264262acb7c0715fede009fa44f3fe6 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Tue, 23 Nov 2021 13:50:03 +0100 Subject: [PATCH 1/7] structlog: migrate application code to better logging Initial work to migrate our application to structlog for better logging, making them compatible with New Relic's integration. There are more work that can be done here to make it better. For example, more usage of `log.bind` to avoid repetition. Besides, rewriting some log message and reduce them to have more Canonical Log Lines (https://www.structlog.org/en/stable/logging-best-practices.html#canonical-log-lines) instead. --- readthedocs/analytics/utils.py | 6 +- readthedocs/api/v2/client.py | 10 +- readthedocs/api/v2/mixins.py | 4 +- readthedocs/api/v2/utils.py | 18 +- readthedocs/api/v2/views/footer_views.py | 4 +- readthedocs/api/v2/views/integrations.py | 46 ++-- readthedocs/api/v2/views/model_views.py | 8 +- readthedocs/api/v2/views/task_views.py | 4 +- readthedocs/audit/apps.py | 4 +- readthedocs/builds/apps.py | 4 +- readthedocs/builds/automation_actions.py | 9 +- readthedocs/builds/filters.py | 4 +- readthedocs/builds/managers.py | 6 +- readthedocs/builds/models.py | 15 +- readthedocs/builds/querysets.py | 12 +- readthedocs/builds/storage.py | 21 +- readthedocs/builds/tasks.py | 138 +++++----- readthedocs/builds/views.py | 14 +- readthedocs/core/adapters.py | 8 +- readthedocs/core/forms.py | 4 +- readthedocs/core/history.py | 8 +- readthedocs/core/logs.py | 3 +- .../core/management/commands/clean_builds.py | 19 +- .../management/commands/contact_owners.py | 4 +- readthedocs/core/management/commands/pull.py | 4 +- .../core/management/commands/update_repos.py | 20 +- readthedocs/core/middleware.py | 6 +- readthedocs/core/resolver.py | 6 +- readthedocs/core/signals.py | 4 +- readthedocs/core/tasks.py | 6 +- readthedocs/core/unresolver.py | 12 +- readthedocs/core/utils/__init__.py | 39 +-- readthedocs/core/utils/contact.py | 12 +- readthedocs/core/views/__init__.py | 4 +- readthedocs/core/views/hooks.py | 53 ++-- readthedocs/doc_builder/backends/mkdocs.py | 14 +- readthedocs/doc_builder/backends/sphinx.py | 18 +- readthedocs/doc_builder/base.py | 10 +- readthedocs/doc_builder/constants.py | 4 +- readthedocs/doc_builder/environments.py | 137 ++++------ .../doc_builder/python_environments.py | 42 ++- readthedocs/embed/v3/views.py | 14 +- readthedocs/embed/views.py | 7 +- readthedocs/forms.py | 24 +- readthedocs/gold/views.py | 31 ++- readthedocs/notifications/notification.py | 18 +- .../oauth/migrations/0003_move_github.py | 12 +- readthedocs/oauth/services/base.py | 14 +- readthedocs/oauth/services/bitbucket.py | 62 +++-- readthedocs/oauth/services/github.py | 95 ++++--- readthedocs/oauth/services/gitlab.py | 89 ++++--- readthedocs/oauth/tasks.py | 22 +- readthedocs/oauth/utils.py | 4 +- readthedocs/organizations/signals.py | 6 +- readthedocs/organizations/tasks.py | 8 +- readthedocs/organizations/utils.py | 12 +- readthedocs/organizations/views/public.py | 4 +- readthedocs/payments/utils.py | 15 +- readthedocs/projects/constants.py | 2 - readthedocs/projects/filters.py | 4 +- readthedocs/projects/models.py | 9 +- readthedocs/projects/tasks.py | 242 +++++++----------- readthedocs/projects/utils.py | 4 +- readthedocs/projects/views/base.py | 17 +- readthedocs/projects/views/private.py | 8 +- readthedocs/projects/views/public.py | 6 +- readthedocs/proxito/middleware.py | 54 ++-- readthedocs/proxito/views/decorators.py | 13 +- readthedocs/proxito/views/mixins.py | 42 +-- readthedocs/proxito/views/serve.py | 46 ++-- readthedocs/proxito/views/utils.py | 8 +- readthedocs/redirects/models.py | 14 +- readthedocs/redirects/querysets.py | 4 +- readthedocs/redirects/utils.py | 4 +- readthedocs/rtd_tests/base.py | 4 +- .../tests/test_build_notifications.py | 4 +- readthedocs/rtd_tests/tests/test_celery.py | 4 +- readthedocs/rtd_tests/tests/test_oauth.py | 145 +++++------ readthedocs/rtd_tests/tests/test_privacy.py | 11 +- readthedocs/rtd_tests/tests/test_redirects.py | 3 - readthedocs/rtd_tests/utils.py | 4 +- readthedocs/search/api.py | 4 +- readthedocs/search/documents.py | 4 +- readthedocs/search/faceted_search.py | 4 +- .../commands/reindex_elasticsearch.py | 43 ++-- readthedocs/search/parsers.py | 53 ++-- readthedocs/search/signals.py | 4 +- readthedocs/search/tasks.py | 50 ++-- readthedocs/search/utils.py | 38 ++- readthedocs/search/views.py | 5 +- readthedocs/settings/base.py | 14 +- readthedocs/settings/proxito/base.py | 6 +- readthedocs/sso/admin.py | 10 +- readthedocs/vcs_support/backends/git.py | 6 +- readthedocs/vcs_support/base.py | 4 +- readthedocs/vcs_support/utils.py | 50 ++-- readthedocs/worker.py | 6 + 97 files changed, 1059 insertions(+), 1095 deletions(-) diff --git a/readthedocs/analytics/utils.py b/readthedocs/analytics/utils.py index 0119005c540..61a02c7e826 100644 --- a/readthedocs/analytics/utils.py +++ b/readthedocs/analytics/utils.py @@ -4,7 +4,7 @@ import hashlib import ipaddress -import logging +import structlog import requests from django.conf import settings @@ -13,7 +13,7 @@ from user_agents import parse -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa def get_client_ip(request): @@ -79,7 +79,7 @@ def send_to_analytics(data): data['ua'] = anonymize_user_agent(data['ua']) resp = None - log.debug('Sending data to analytics: %s', data) + log.debug('Sending data to analytics.', data=data) try: resp = requests.post( 'https://www.google-analytics.com/collect', diff --git a/readthedocs/api/v2/client.py b/readthedocs/api/v2/client.py index 599e169e283..a89d35737ce 100644 --- a/readthedocs/api/v2/client.py +++ b/readthedocs/api/v2/client.py @@ -1,6 +1,6 @@ """Simple client to access our API with Slumber credentials.""" -import logging +import structlog import requests from django.conf import settings @@ -10,7 +10,7 @@ from .adapters import TimeoutHostHeaderSSLAdapter, TimeoutHTTPAdapter -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class DrfJsonSerializer(serialize.JsonSerializer): @@ -63,9 +63,9 @@ def setup_api(): } if settings.SLUMBER_USERNAME and settings.SLUMBER_PASSWORD: log.debug( - 'Using slumber v2 with user %s, pointed at %s', - settings.SLUMBER_USERNAME, - settings.SLUMBER_API_HOST, + 'Using slumber v2.', + username=settings.SLUMBER_USERNAME, + api_host=settings.SLUMBER_API_HOST, ) session.auth = (settings.SLUMBER_USERNAME, settings.SLUMBER_PASSWORD) else: diff --git a/readthedocs/api/v2/mixins.py b/readthedocs/api/v2/mixins.py index 99cf94b4edf..dfc522b538e 100644 --- a/readthedocs/api/v2/mixins.py +++ b/readthedocs/api/v2/mixins.py @@ -1,6 +1,6 @@ -import logging +import structlog -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class CachedResponseMixin: diff --git a/readthedocs/api/v2/utils.py b/readthedocs/api/v2/utils.py index 9788f4b553f..055e131954d 100644 --- a/readthedocs/api/v2/utils.py +++ b/readthedocs/api/v2/utils.py @@ -1,7 +1,7 @@ """Utility functions that are used by both views and celery tasks.""" import itertools -import logging +import structlog from rest_framework.pagination import PageNumberPagination @@ -17,7 +17,7 @@ ) from readthedocs.builds.models import RegexAutomationRule, Version -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def sync_versions_to_db(project, versions, type): # pylint: disable=redefined-builtin @@ -86,9 +86,9 @@ def sync_versions_to_db(project, versions, type): # pylint: disable=redefined-b ) log.info( - '(Sync Versions) Updated Version: [%s=%s] ', - version_name, - version_id, + 'Re-syncing versions: version updated.', + version_verbose_name=version_name, + version_id=version_id, ) else: # New Version @@ -116,8 +116,9 @@ def sync_versions_to_db(project, versions, type): # pylint: disable=redefined-b latest_version.save() if added: log.info( - '(Sync Versions) Added Versions: versions_count=%d versions=[%s]', - len(added), ' '.join(itertools.islice(added, 100)), + 'Re-syncing versions: versions added.', + count=len(added), + versions=','.join(itertools.islice(added, 100)), ) return added @@ -214,8 +215,7 @@ def delete_versions_from_db(project, tags_data, branches_data): _, deleted = to_delete_qs.delete() versions_count = deleted.get('builds.Version', 0) log.info( - '(Sync Versions) Deleted Versions: project=%s versions_count=%s', - project.slug, versions_count, + 'Re-syncing versions: versions deleted.', project_slug=project.slug, count=versions_count, ) diff --git a/readthedocs/api/v2/views/footer_views.py b/readthedocs/api/v2/views/footer_views.py index 6226bcf0146..ae69b110728 100644 --- a/readthedocs/api/v2/views/footer_views.py +++ b/readthedocs/api/v2/views/footer_views.py @@ -1,6 +1,6 @@ """Endpoint to generate footer HTML.""" -import logging +import structlog import re from functools import lru_cache @@ -24,7 +24,7 @@ parse_version_failsafe, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def get_version_compare_data(project, base_version=None): diff --git a/readthedocs/api/v2/views/integrations.py b/readthedocs/api/v2/views/integrations.py index 065b3edfb41..7857e79912b 100644 --- a/readthedocs/api/v2/views/integrations.py +++ b/readthedocs/api/v2/views/integrations.py @@ -3,7 +3,7 @@ import hashlib import hmac import json -import logging +import structlog import re from django.shortcuts import get_object_or_404 @@ -29,7 +29,7 @@ from readthedocs.integrations.models import HttpExchange, Integration from readthedocs.projects.models import Feature, Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) GITHUB_EVENT_HEADER = 'HTTP_X_GITHUB_EVENT' GITHUB_SIGNATURE_HEADER = 'HTTP_X_HUB_SIGNATURE' @@ -86,8 +86,9 @@ def post(self, request, project_slug): raise NotFound('Project not found') if not self.is_payload_valid(): log.warning( - 'Invalid payload for project: %s and integration: %s', - project_slug, self.integration_type + 'Invalid payload for project and integration.', + project_slug=project_slug, + integration_type=self.integration_type, ) return Response( {'detail': self.invalid_payload_msg}, @@ -184,9 +185,9 @@ def get_response_push(self, project, branches): to_build, not_building = build_branches(project, branches) if not_building: log.info( - 'Skipping project branches: project=%s branches=%s', - project, - branches, + 'Skipping project branches.', + project_slug=project.slug, + branches=branches, ) triggered = bool(to_build) return { @@ -338,8 +339,8 @@ def is_payload_valid(self): secret = self.get_integration().secret if not secret: log.info( - 'Skipping payload signature validation. project=%s', - self.project.slug, + 'Skipping payload signature validation.', + project_slug=self.project.slug, ) return True if not signature: @@ -405,7 +406,11 @@ def handle_webhook(self): # Sync versions when a branch/tag was created/deleted if event in (GITHUB_CREATE, GITHUB_DELETE): - log.info('Triggered sync_versions: project=%s event=%s', self.project, event) + log.info( + 'Triggered sync_versions.', + project_slug=self.project.slug, + webhook_event=event, + ) return self.sync_versions_response(self.project) # Handle pull request events @@ -441,7 +446,7 @@ def handle_webhook(self): # already have the CREATE/DELETE events. So we don't trigger the sync twice. return self.sync_versions_response(self.project, sync=False) - log.info('Triggered sync_versions: project=%s events=%s', self.project, events) + log.info('Triggered sync_versions.', project_slug=self.project.slug, events=events) return self.sync_versions_response(self.project) # Trigger a build for all branches in the push @@ -512,8 +517,8 @@ def is_payload_valid(self): secret = self.get_integration().secret if not secret: log.info( - 'Skipping payload signature validation. project=%s', - self.project.slug, + 'Skipping payload signature validation.', + project_slug=self.project.slug, ) return True if not token: @@ -554,8 +559,12 @@ def handle_webhook(self): after = data.get('after') # Tag/branch created/deleted if GITLAB_NULL_HASH in (before, after): - log.info('Triggered sync_versions: project=%s before=%s after=%s', - self.project, before, after) + log.info( + 'Triggered sync_versions.', + project_slug=self.project.slug, + before=before, + after=after, + ) return self.sync_versions_response(self.project) # Normal push to master try: @@ -652,8 +661,11 @@ def handle_webhook(self): # will be triggered with the normal push. if branches: return self.get_response_push(self.project, branches) - log.info('Triggered sync_versions: project=%s event=%s', - self.project, event) + log.info( + 'Triggered sync_versions.', + project_slug=self.project.slug, + webhook_event=event, + ) return self.sync_versions_response(self.project) except KeyError: raise ParseError('Invalid request') diff --git a/readthedocs/api/v2/views/model_views.py b/readthedocs/api/v2/views/model_views.py index 2b802757ed2..a36c443147d 100644 --- a/readthedocs/api/v2/views/model_views.py +++ b/readthedocs/api/v2/views/model_views.py @@ -1,7 +1,7 @@ """Endpoints for listing Projects, Versions, Builds, etc.""" import json -import logging +import structlog from allauth.socialaccount.models import SocialAccount from django.conf import settings @@ -40,7 +40,7 @@ RemoteProjectPagination, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class PlainTextBuildRenderer(BaseRenderer): @@ -269,8 +269,8 @@ def retrieve(self, *args, **kwargs): data['commands'] = json.loads(json_resp) except Exception: log.exception( - 'Failed to read build data from storage. path=%s.', - storage_path, + 'Failed to read build data from storage.', + path=storage_path, ) return Response(data) diff --git a/readthedocs/api/v2/views/task_views.py b/readthedocs/api/v2/views/task_views.py index dfb34adc6c2..b5271271641 100644 --- a/readthedocs/api/v2/views/task_views.py +++ b/readthedocs/api/v2/views/task_views.py @@ -1,6 +1,6 @@ """Endpoints relating to task/job status, etc.""" -import logging +import structlog from django.urls import reverse from redis import ConnectionError @@ -12,7 +12,7 @@ from readthedocs.oauth import tasks -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) SUCCESS_STATES = ('SUCCESS',) FAILURE_STATES = ( diff --git a/readthedocs/audit/apps.py b/readthedocs/audit/apps.py index 38996bf6569..34e189971d3 100644 --- a/readthedocs/audit/apps.py +++ b/readthedocs/audit/apps.py @@ -1,10 +1,10 @@ """Audit module.""" -import logging +import structlog from django.apps import AppConfig -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class AuditConfig(AppConfig): diff --git a/readthedocs/builds/apps.py b/readthedocs/builds/apps.py index 3f8728ec4ed..8df02cd747d 100644 --- a/readthedocs/builds/apps.py +++ b/readthedocs/builds/apps.py @@ -1,9 +1,9 @@ -import logging +import structlog from django.apps import AppConfig from django.utils.translation import ugettext_lazy as _ -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Config(AppConfig): diff --git a/readthedocs/builds/automation_actions.py b/readthedocs/builds/automation_actions.py index 2be65058334..93de835f669 100644 --- a/readthedocs/builds/automation_actions.py +++ b/readthedocs/builds/automation_actions.py @@ -8,12 +8,12 @@ - action_arg: An additional argument to apply the action """ -import logging +import structlog from readthedocs.core.utils import trigger_build from readthedocs.projects.constants import PRIVATE, PUBLIC -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def activate_version(version, match_result, action_arg, *args, **kwargs): @@ -72,8 +72,9 @@ def delete_version(version, match_result, action_arg, *args, **kwargs): """Delete a version if isn't marked as the default version.""" if version.project.default_version == version.slug: log.info( - "Skipping deleting default version. project=%s version=%s", - version.project.slug, version.slug, + "Skipping deleting default version.", + project_slug=version.project.slug, + version_slug=version.slug, ) return version.delete() diff --git a/readthedocs/builds/filters.py b/readthedocs/builds/filters.py index 45862e9a1d1..6c851183780 100644 --- a/readthedocs/builds/filters.py +++ b/readthedocs/builds/filters.py @@ -1,4 +1,4 @@ -import logging +import structlog from django.forms.widgets import HiddenInput from django.utils.translation import ugettext_lazy as _ @@ -6,7 +6,7 @@ from readthedocs.builds.constants import BUILD_STATE_FINISHED -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BuildListFilter(FilterSet): diff --git a/readthedocs/builds/managers.py b/readthedocs/builds/managers.py index 7f13f88f6a0..cf82b8b209b 100644 --- a/readthedocs/builds/managers.py +++ b/readthedocs/builds/managers.py @@ -1,6 +1,6 @@ """Build and Version class model Managers.""" -import logging +import structlog from django.core.exceptions import ObjectDoesNotExist from django.db import models @@ -18,7 +18,7 @@ from readthedocs.builds.querysets import VersionQuerySet from readthedocs.core.utils.extend import get_override_class -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) __all__ = ['VersionManager'] @@ -78,7 +78,7 @@ def get_object_or_log(self, **kwargs): try: return super().get(**kwargs) except ObjectDoesNotExist: - log.warning('Version not found for given kwargs. %s', kwargs) + log.warning('Version not found for given kwargs.', kwargs=kwargs) class InternalVersionManager(VersionManager): diff --git a/readthedocs/builds/models.py b/readthedocs/builds/models.py index 3296c56743c..45595d414ac 100644 --- a/readthedocs/builds/models.py +++ b/readthedocs/builds/models.py @@ -1,7 +1,7 @@ """Models for the builds app.""" import datetime -import logging +import structlog import os.path import re from functools import partial @@ -88,7 +88,7 @@ from readthedocs.projects.version_handling import determine_stable_version from readthedocs.storage import build_environment_storage -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Version(TimeStampedModel): @@ -318,7 +318,7 @@ def get_absolute_url(self): def delete(self, *args, **kwargs): # pylint: disable=arguments-differ from readthedocs.projects import tasks - log.info('Removing files for version %s', self.slug) + log.info('Removing files for version.', version_slug=self.slug) tasks.clean_project_resources(self.project, self) super().delete(*args, **kwargs) @@ -422,7 +422,7 @@ def clean_build_path(self): try: path = self.get_build_path() if path is not None: - log.debug('Removing build path %s for %s', path, self) + log.debug('Removing build path for project.', path=path, project_slug=self.slug) rmtree(path) except OSError: log.exception('Build path cleanup failed') @@ -1302,11 +1302,12 @@ def match(self, version, match_arg): return bool(match), match except TimeoutError: log.warning( - 'Timeout while parsing regex. pattern=%s, input=%s', - match_arg, version.verbose_name, + 'Timeout while parsing regex.', + pattern=match_arg, + version_slug=version.slug, ) except Exception as e: - log.info('Error parsing regex: %s', e) + log.exception('Error parsing regex.', exc_info=True) return False, None def get_edit_url(self): diff --git a/readthedocs/builds/querysets.py b/readthedocs/builds/querysets.py index 1d057d22f7e..c8aa96beb66 100644 --- a/readthedocs/builds/querysets.py +++ b/readthedocs/builds/querysets.py @@ -1,6 +1,6 @@ """Build and Version QuerySet classes.""" import datetime -import logging +import structlog from django.db import models from django.db.models import Q @@ -16,7 +16,7 @@ from readthedocs.projects import constants from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) __all__ = ['VersionQuerySet', 'BuildQuerySet', 'RelatedBuildQuerySet'] @@ -231,10 +231,10 @@ def concurrent(self, project): max_concurrent = Project.objects.max_concurrent_builds(project) log.info( - 'Concurrent builds. project=%s running=%s max=%s', - project.slug, - concurrent, - max_concurrent, + 'Concurrent builds.', + project_slug=project.slug, + concurent=concurrent, + max_concurrent=max_concurrent, ) if concurrent >= max_concurrent: limit_reached = True diff --git a/readthedocs/builds/storage.py b/readthedocs/builds/storage.py index 630c09c9a94..9087c4e9732 100644 --- a/readthedocs/builds/storage.py +++ b/readthedocs/builds/storage.py @@ -1,4 +1,4 @@ -import logging +import structlog from pathlib import Path from django.conf import settings @@ -6,7 +6,7 @@ from django.core.files.storage import FileSystemStorage from storages.utils import get_available_overwrite_name, safe_join -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BuildMediaStorageMixin: @@ -59,7 +59,7 @@ def delete_directory(self, path): if path in ('', '/'): raise SuspiciousFileOperation('Deleting all storage cannot be right') - log.debug('Deleting directory %s from media storage', path) + log.debug('Deleting path from media storage', path=path) folders, files = self.listdir(self._dirpath(path)) for folder_name in folders: if folder_name: @@ -76,7 +76,11 @@ def copy_directory(self, source, destination): :param source: the source path on the local disk :param destination: the destination path in storage """ - log.debug('Copying source directory %s to media storage at %s', source, destination) + log.debug( + 'Copying source directory to media storage', + source=source, + destination=destination, + ) source = Path(source) for filepath in source.iterdir(): sub_destination = self.join(destination, filepath.name) @@ -101,8 +105,9 @@ def sync_directory(self, source, destination): raise SuspiciousFileOperation('Syncing all storage cannot be right') log.debug( - 'Syncing to media storage. source=%s destination=%s', - source, destination, + 'Syncing to media storage.', + source=source, + destination=destination, ) source = Path(source) copied_files = set() @@ -126,7 +131,7 @@ def sync_directory(self, source, destination): for filename in dest_files: if filename not in copied_files: filepath = self.join(destination, filename) - log.debug('Deleting file from media storage. file=%s', filepath) + log.debug('Deleting file from media storage.', filepath=filepath) self.delete(filepath) def join(self, directory, filepath): @@ -136,7 +141,7 @@ def walk(self, top): if top in ('', '/'): raise SuspiciousFileOperation('Iterating all storage cannot be right') - log.debug('Walking %s in media storage', top) + log.debug('Walking path in media storage', path=top) folders, files = self.listdir(self._dirpath(top)) yield top, folders, files diff --git a/readthedocs/builds/tasks.py b/readthedocs/builds/tasks.py index f2397e07801..5143792b000 100644 --- a/readthedocs/builds/tasks.py +++ b/readthedocs/builds/tasks.py @@ -1,5 +1,5 @@ import json -import logging +import structlog from datetime import datetime, timedelta from io import BytesIO @@ -37,7 +37,7 @@ from readthedocs.storage import build_commands_storage from readthedocs.worker import app -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class TaskRouter: @@ -66,17 +66,17 @@ class TaskRouter: BUILD_LARGE_QUEUE = 'build:large' def route_for_task(self, task, args, kwargs, **__): - log.info('Executing TaskRouter. task=%s', task) + log.info('Executing TaskRouter.', task=task) if task not in ( 'readthedocs.projects.tasks.update_docs_task', 'readthedocs.projects.tasks.sync_repository_task', ): - log.info('Skipping routing non-build task. task=%s', task) + log.info('Skipping routing non-build task.', task=task) return version = self._get_version(task, args, kwargs) if not version: - log.info('No Build/Version found. No routing task. task=%s', task) + log.info('No Build/Version found. No routing task.', task=task) return project = version.project @@ -84,8 +84,9 @@ def route_for_task(self, task, args, kwargs, **__): # Do not override the queue defined in the project itself if project.build_queue: log.info( - 'Skipping routing task because project has a custom queue. project=%s queue=%s', - project.slug, project.build_queue, + 'Skipping routing task because project has a custom queue.', + project_slug=project.slug, + queue=project.build_queue, ) return project.build_queue @@ -105,8 +106,9 @@ def route_for_task(self, task, args, kwargs, **__): else: routing_queue = self.BUILD_LARGE_QUEUE log.info( - 'Routing task because is a external version. project=%s queue=%s', - project.slug, routing_queue, + 'Routing task because is a external version.', + project_slug=project.slug, + queue=routing_queue, ) return routing_queue @@ -115,8 +117,9 @@ def route_for_task(self, task, args, kwargs, **__): for build in last_builds.iterator(): if build.config.get('conda', None): log.info( - 'Routing task because project uses conda. project=%s queue=%s', - project.slug, self.BUILD_LARGE_QUEUE, + 'Routing task because project uses conda.', + project_slug=project.slug, + queue=self.BUILD_LARGE_QUEUE, ) return self.BUILD_LARGE_QUEUE @@ -129,13 +132,16 @@ def route_for_task(self, task, args, kwargs, **__): # We do not have enough builds for this version yet if successful_builds_count < self.MIN_SUCCESSFUL_BUILDS: log.info( - 'Routing task because it does not have enough successful builds yet. ' - 'project=%s queue=%s', - project.slug, self.BUILD_LARGE_QUEUE, + 'Routing task because it does not have enough successful builds yet.', + project_slug=project.slug, + queue=self.BUILD_LARGE_QUEUE, ) return self.BUILD_LARGE_QUEUE - log.info('No routing task because no conditions were met. project=%s', project.slug) + log.info( + 'No routing task because no conditions were met.', + project_slug=project.slug, + ) return def _get_version(self, task, args, kwargs): @@ -150,8 +156,8 @@ def _get_version(self, task, args, kwargs): version = Version.objects.get(pk=version_pk) except Version.DoesNotExist: log.info( - 'Version does not exist. Routing task to default queue. version_pk=%s', - version_pk, + 'Version does not exist. Routing task to default queue.', + version_id=version_pk, ) return version @@ -199,7 +205,7 @@ def archive_builds_task(days=14, limit=200, include_cold=False, delete=False): if len(cmd['output']) > MAX_BUILD_COMMAND_SIZE: cmd['output'] = cmd['output'][-MAX_BUILD_COMMAND_SIZE:] cmd['output'] = "... (truncated) ...\n\nCommand output too long. Truncated to last 1MB.\n\n" + cmd['output'] # noqa - log.warning('Truncating build command for build. build=%s', build.pk) + log.warning('Truncating build command for build.', build_id=build.id) output = BytesIO() output.write(json.dumps(data).encode('utf8')) output.seek(0) @@ -241,13 +247,15 @@ def delete_inactive_external_versions(limit=200, days=30 * 3): ) except Exception: log.exception( - "Failed to send status: project=%s version=%s", - version.project.slug, version.slug, + "Failed to send status", + project_slug=version.project.slug, + version_slug=version.slug, ) else: log.info( - "Removing external version. project=%s version=%s", - version.project.slug, version.slug, + "Removing external version.", + project_slug=version.project.slug, + version_slug=version.slug, ) version.delete() @@ -270,9 +278,6 @@ def sync_versions_task(project_pk, tags_data, branches_data, **kwargs): """ project = Project.objects.get(pk=project_pk) - # TODO: remove this log once we find out what's causing OOM - log.info('Running readthedocs.builds.tasks.sync_versions_task. locals=%s', locals()) - # If the currently highest non-prerelease version is active, then make # the new latest version active as well. current_stable = project.get_original_stable_version() @@ -321,8 +326,9 @@ def sync_versions_task(project_pk, tags_data, branches_data, **kwargs): # Don't interrupt the request if something goes wrong # in the automation rules. log.exception( - 'Failed to execute automation rules for [%s]: %s', - project.slug, added_versions + 'Failed to execute automation rules.', + project_slug=project.slug, + versions=added_versions, ) # TODO: move this to an automation rule @@ -330,11 +336,9 @@ def sync_versions_task(project_pk, tags_data, branches_data, **kwargs): new_stable = project.get_stable_version() if promoted_version and new_stable and new_stable.active: log.info( - 'Triggering new stable build: %(project)s:%(version)s', - { - 'project': project.slug, - 'version': new_stable.identifier, - } + 'Triggering new stable build.', + project_slug=project.slug, + version_identifier=new_stable.identifier, ) trigger_build(project=project, version=new_stable) @@ -375,7 +379,7 @@ def send_build_status(build_pk, commit, status, link_to_build=False): provider_name = build.project.git_provider_name - log.info('Sending build status. build=%s project=%s', build.pk, build.project.slug) + log.info('Sending build status.', build_id=build.id, project_slug=build.project.slug) if provider_name in [GITHUB_BRAND, GITLAB_BRAND]: # get the service class for the project e.g: GitHubService. @@ -408,19 +412,18 @@ def send_build_status(build_pk, commit, status, link_to_build=False): if success: log.info( - 'Build status report sent correctly. ' - 'project=%s build=%s status=%s commit=%s user=%s', - build.project.slug, - build.pk, - status, - commit, - relation.user.username, + 'Build status report sent correctly.', + project_slug=build.project.slug, + build_id=build.id, + status=status, + commit=commit, + user_username=relation.user.username, ) return True else: log.warning( - 'Project does not have a RemoteRepository. project=%s', - build.project.slug, + 'Project does not have a RemoteRepository.', + project_slug=build.project.slug, ) # Try to send build status for projects with no RemoteRepository for user in users: @@ -431,13 +434,12 @@ def send_build_status(build_pk, commit, status, link_to_build=False): success = service.send_build_status(build, commit, status) if success: log.info( - 'Build status report sent correctly using an user account. ' - 'project=%s build=%s status=%s commit=%s user=%s', - build.project.slug, - build.pk, - status, - commit, - user.username, + 'Build status report sent correctly using an user account.', + project_slug=build.project.slug, + build_id=build.id, + status=status, + commit=commit, + user_username=user.username, ) return True @@ -453,8 +455,8 @@ def send_build_status(build_pk, commit, status, link_to_build=False): notification.send() log.info( - 'No social account or repository permission available. project=%s', - build.project.slug + 'No social account or repository permission available.', + project_slug=build.project.slug, ) return False @@ -504,9 +506,11 @@ def send(self): self.send_email(email) except Exception: log.exception( - 'Failed to send email notification. ' - 'email=%s project=%s version=%s build=%s', - email, self.project.slug, self.version.slug, self.build.pk, + 'Failed to send email notification.', + email=email, + project_slug=self.project.slug, + version_slug=self.version.slug, + build_id=self.build.id, ) webhooks = ( @@ -518,8 +522,11 @@ def send(self): self.send_webhook(webhook) except Exception: log.exception( - 'Failed to send webhook. webhook=%s project=%s version=%s build=%s', - webhook.id, self.project.slug, self.version.slug, self.build.pk, + 'Failed to send webhook.', + webhook_id=webhook.id, + project_slug=self.project.slug, + version_slug=self.version.slug, + build_id=self.build.id, ) def send_email(self, email): @@ -561,8 +568,11 @@ def send_email(self, email): ) log.info( - 'Sending email notification. email=%s project=%s version=%s build=%s', - email, self.project.slug, self.version.slug, self.build.id, + 'Sending email notification.', + email=email, + project_slug=self.project.slug, + version_slug=self.version.slug, + build_id=self.build.id, ) send_email( email, @@ -614,8 +624,11 @@ def send_webhook(self, webhook): try: log.info( - 'Sending webhook notification. webhook=%s project=%s version=%s build=%s', - webhook.pk, self.project.slug, self.version.slug, self.build.pk, + 'Sending webhook notification.', + webhook_id=webhook.id, + project_slug=self.project.slug, + version_slug=self.version.slug, + build_id=self.build.id, ) response = requests.post( webhook.url, @@ -629,6 +642,7 @@ def send_webhook(self, webhook): ) except Exception: log.exception( - 'Failed to POST to webhook url. webhook=%s url=%s', - webhook.pk, webhook.url, + 'Failed to POST to webhook url.', + webhook_id=webhook.id, + webhook_url=webhook.url, ) diff --git a/readthedocs/builds/views.py b/readthedocs/builds/views.py index b8a1146b7d0..58cab4cfbce 100644 --- a/readthedocs/builds/views.py +++ b/readthedocs/builds/views.py @@ -1,6 +1,6 @@ """Views for builds app.""" -import logging +import structlog import textwrap from urllib.parse import urlparse @@ -21,7 +21,7 @@ from readthedocs.doc_builder.exceptions import BuildEnvironmentError from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BuildBase: @@ -81,11 +81,11 @@ def post(self, request, project_slug): if build_to_retrigger: commit_to_retrigger = build_to_retrigger.commit log.info( - 'Re-triggering build. project=%s version=%s commit=%s build=%s', - project.slug, - version.slug, - build_to_retrigger.commit, - build_to_retrigger.pk + 'Re-triggering build.', + project_slug=project.slug, + version_slug=version.slug, + build_commit=build_to_retrigger.commit, + build_id=build_to_retrigger.pk, ) else: # Use generic query when triggering a normal build diff --git a/readthedocs/core/adapters.py b/readthedocs/core/adapters.py index 6f4339d3219..4ece0428c4a 100644 --- a/readthedocs/core/adapters.py +++ b/readthedocs/core/adapters.py @@ -1,7 +1,7 @@ """Allauth overrides.""" import json -import logging +import structlog from allauth.account.adapter import DefaultAccountAdapter from django.conf import settings @@ -11,7 +11,7 @@ from readthedocs.core.utils import send_email from readthedocs.organizations.models import TeamMember -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class AccountAdapter(DefaultAccountAdapter): @@ -40,8 +40,8 @@ def send_mail(self, template_prefix, email, context): del context[key] if removed_keys: log.debug( - 'Removed context we were unable to serialize: %s', - removed_keys, + 'Removed context we were unable to serialize.', + removed_keys=removed_keys, ) send_email( diff --git a/readthedocs/core/forms.py b/readthedocs/core/forms.py index 7f311951a24..4996f4e346e 100644 --- a/readthedocs/core/forms.py +++ b/readthedocs/core/forms.py @@ -1,6 +1,6 @@ """Forms for core app.""" -import logging +import structlog from django import forms from django.contrib.auth.models import User @@ -11,7 +11,7 @@ from .models import UserProfile -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class UserProfileForm(forms.ModelForm): diff --git a/readthedocs/core/history.py b/readthedocs/core/history.py index e1c3e193143..2ae7c64312c 100644 --- a/readthedocs/core/history.py +++ b/readthedocs/core/history.py @@ -1,4 +1,4 @@ -import logging +import structlog from functools import partial from django import forms @@ -8,7 +8,7 @@ from simple_history.models import HistoricalRecords from simple_history.utils import update_change_reason -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def set_change_reason(instance, reason): @@ -46,8 +46,8 @@ def safe_update_change_reason(instance, reason): update_change_reason(instance=instance, reason=reason) except Exception: log.exception( - 'An error occurred while updating the change reason of the instance: obj=%s', - instance, + 'An error occurred while updating the change reason of the instance.', + instance=instance, ) diff --git a/readthedocs/core/logs.py b/readthedocs/core/logs.py index 75608e89aad..7e8bf9321f7 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -78,7 +78,8 @@ def __call__(self, logger, method_name, event_dict): structlog.stdlib.add_log_level, structlog.stdlib.PositionalArgumentsFormatter(), structlog.processors.StackInfoRenderer(), - structlog.processors.format_exc_info, + # Remove `format_exc_info` from your processor chain if you want pretty exceptions. + # structlog.processors.format_exc_info, structlog.processors.UnicodeDecoder(), structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ], diff --git a/readthedocs/core/management/commands/clean_builds.py b/readthedocs/core/management/commands/clean_builds.py index c04e8f2d187..c49820cee12 100644 --- a/readthedocs/core/management/commands/clean_builds.py +++ b/readthedocs/core/management/commands/clean_builds.py @@ -2,7 +2,7 @@ """Clean up stable build paths per project version.""" -import logging +import structlog from datetime import timedelta from django.core.management.base import BaseCommand @@ -12,7 +12,7 @@ from readthedocs.builds.models import Build, Version -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Command(BaseCommand): @@ -51,17 +51,18 @@ def handle(self, *args, **options): latest_build = version.builds.latest('date') if latest_build.date > max_date: log.warning( - '%s is newer than %s', - latest_build, - max_date, + 'Latest build is newer.', + build_id=latest_build.pk, + date=latest_build.date, + max_date=max_date, ) path = version.get_build_path() if path is not None: log.info( - 'Found stale build path for %s at %s, last used on %s', - version, - path, - latest_build.date, + 'Found stale build path for version at path, last used on date.', + version_slug=version.slug, + path=path, + date=latest_build.date, ) if not options['dryrun']: version.clean_build_path() diff --git a/readthedocs/core/management/commands/contact_owners.py b/readthedocs/core/management/commands/contact_owners.py index 67c267771f0..c84d6fc4c32 100644 --- a/readthedocs/core/management/commands/contact_owners.py +++ b/readthedocs/core/management/commands/contact_owners.py @@ -1,4 +1,4 @@ -import logging +import structlog import sys from pathlib import Path from pprint import pprint @@ -14,7 +14,7 @@ User = get_user_model() # noqa -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Command(BaseCommand): diff --git a/readthedocs/core/management/commands/pull.py b/readthedocs/core/management/commands/pull.py index 8b2a95a2939..93551e034d1 100644 --- a/readthedocs/core/management/commands/pull.py +++ b/readthedocs/core/management/commands/pull.py @@ -2,7 +2,7 @@ """Trigger build for project slug.""" -import logging +import structlog from django.core.management.base import LabelCommand @@ -10,7 +10,7 @@ from readthedocs.projects import tasks, utils -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Command(LabelCommand): diff --git a/readthedocs/core/management/commands/update_repos.py b/readthedocs/core/management/commands/update_repos.py index 8a0aaec6f71..f0dd5e99086 100644 --- a/readthedocs/core/management/commands/update_repos.py +++ b/readthedocs/core/management/commands/update_repos.py @@ -4,7 +4,7 @@ Invoked via ``./manage.py update_repos``. """ -import logging +import structlog from django.core.management.base import BaseCommand @@ -13,7 +13,7 @@ from readthedocs.core.utils import trigger_build from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Command(BaseCommand): @@ -48,7 +48,7 @@ def handle(self, *args, **options): if slugs: for slug in slugs: if version == 'all': - log.info('Updating all versions for %s', slug) + log.info('Updating all versions.', project_slug=slug) for version in Version.objects.filter( project__slug=slug, active=True, @@ -56,7 +56,7 @@ def handle(self, *args, **options): ): trigger_build(project=version.project, version=version) elif version == INTERNAL: - log.info('Updating all internal versions for %s', slug) + log.info('Updating all internal versions.', project_slug=slug) for version in Version.internal.filter( project__slug=slug, active=True, @@ -64,7 +64,7 @@ def handle(self, *args, **options): ): trigger_build(project=version.project, version=version) elif version == EXTERNAL: - log.info('Updating all external versions for %s', slug) + log.info('Updating all external versions.', project_slug=slug) for version in Version.external.filter( project__slug=slug, active=True, @@ -72,7 +72,11 @@ def handle(self, *args, **options): ): trigger_build(project=version.project, version=version) elif version: - log.info('Updating version %s for %s', version, slug) + log.info( + 'Updating version for project.', + version_slug=version.slug, + project_slug=slug, + ) for version in Version.objects.filter( project__slug=slug, slug=version, @@ -80,7 +84,7 @@ def handle(self, *args, **options): trigger_build(project=version.project, version=version) else: p = Project.all_objects.get(slug=slug) - log.info('Building %s', p) + log.info('Building ...', project_slug=p.slug) trigger_build(project=p, force=force) else: if version == 'all': @@ -105,7 +109,7 @@ def handle(self, *args, **options): ): trigger_build(project=version.project, version=version) elif version: - log.info('Updating version %s', version) + log.info('Updating version.', version_slug=version.slug) for version in Version.objects.filter( slug=version, ): diff --git a/readthedocs/core/middleware.py b/readthedocs/core/middleware.py index a768756ce52..8bc21e4f63a 100644 --- a/readthedocs/core/middleware.py +++ b/readthedocs/core/middleware.py @@ -1,4 +1,4 @@ -import logging +import structlog import time from django.conf import settings @@ -13,9 +13,7 @@ from django.utils.http import http_date from django.utils.translation import ugettext_lazy as _ -log = logging.getLogger(__name__) - -LOG_TEMPLATE = '(Middleware) %(msg)s [%(host)s%(path)s]' +log = structlog.get_logger(__name__) class ReadTheDocsSessionMiddleware(SessionMiddleware): diff --git a/readthedocs/core/resolver.py b/readthedocs/core/resolver.py index 00e3bee8eb2..43f515462be 100644 --- a/readthedocs/core/resolver.py +++ b/readthedocs/core/resolver.py @@ -1,6 +1,6 @@ """URL resolver for documentation.""" -import logging +import structlog from urllib.parse import urlunparse from django.conf import settings @@ -8,7 +8,7 @@ from readthedocs.core.utils.extend import SettingsOverrideObject from readthedocs.builds.constants import EXTERNAL -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class ResolverBase: @@ -102,7 +102,7 @@ def base_resolve_path( ) if '$' in url: log.warning( - 'Unconverted variable in a resolver URLConf: url=%s', url + 'Unconverted variable in a resolver URLConf.', url=url, ) return url.format( diff --git a/readthedocs/core/signals.py b/readthedocs/core/signals.py index 23ae9583293..bc65056e18b 100644 --- a/readthedocs/core/signals.py +++ b/readthedocs/core/signals.py @@ -1,6 +1,6 @@ """Signal handling for core app.""" -import logging +import structlog from corsheaders import signals from django.conf import settings @@ -17,7 +17,7 @@ from readthedocs.core.unresolver import unresolve from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) ALLOWED_URLS = [ '/api/v2/footer_html', diff --git a/readthedocs/core/tasks.py b/readthedocs/core/tasks.py index 6969b619e0a..99e9bb6ca29 100644 --- a/readthedocs/core/tasks.py +++ b/readthedocs/core/tasks.py @@ -2,7 +2,7 @@ """Basic tasks.""" -import logging +import structlog from django.conf import settings from django.core.mail import EmailMultiAlternatives @@ -14,7 +14,7 @@ from readthedocs.worker import app -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) EMAIL_TIME_LIMIT = 30 @@ -60,7 +60,7 @@ def send_email_task( # TypeError is raised when ``template_html`` is ``None`` pass msg.send() - log.info('Sent email to recipient: %s', recipient) + log.info('Sent email to recipient.', recipient=recipient) @app.task(queue='web') diff --git a/readthedocs/core/unresolver.py b/readthedocs/core/unresolver.py index 38677f94828..7ba6a2858fa 100644 --- a/readthedocs/core/unresolver.py +++ b/readthedocs/core/unresolver.py @@ -1,4 +1,4 @@ -import logging +import structlog from collections import namedtuple from urllib.parse import urlparse @@ -10,7 +10,7 @@ from readthedocs.proxito.views.mixins import ServeDocsMixin from readthedocs.proxito.views.utils import _get_project_data_from_request -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) UnresolvedObject = namedtuple( 'Unresolved', 'project, language_slug, version_slug, filename, fragment') @@ -80,9 +80,11 @@ def unresolve_from_request(self, request, path): filename += 'index.html' log.info( - 'Unresolver parsed: ' - 'project=%s lang_slug=%s version_slug=%s filename=%s', - final_project.slug, lang_slug, version_slug, filename + 'Unresolver parsed.', + project_slug=final_project.slug, + lang_slug=lang_slug, + version_slug=version_slug, + filename=filename, ) return UnresolvedObject(final_project, lang_slug, version_slug, filename, parsed.fragment) diff --git a/readthedocs/core/utils/__init__.py b/readthedocs/core/utils/__init__.py index 6ef577877ed..8b04f275471 100644 --- a/readthedocs/core/utils/__init__.py +++ b/readthedocs/core/utils/__init__.py @@ -2,7 +2,7 @@ import datetime import errno -import logging +import structlog import os import re @@ -28,7 +28,7 @@ CELERY_MEDIUM, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def prepare_build( @@ -66,8 +66,8 @@ def prepare_build( build = None if not Project.objects.is_active(project): log.warning( - 'Build not triggered because Project is not active: project=%s', - project.slug, + 'Build not triggered because project is not active.', + project_slug=project.slug, ) return (None, None) @@ -108,7 +108,7 @@ def prepare_build( if project.container_time_limit: time_limit = int(project.container_time_limit) except ValueError: - log.warning('Invalid time_limit for project: %s', project.slug) + log.warning('Invalid time_limit for project.', project_slug=project.slug) # Add 20% overhead to task, to ensure the build can timeout and the task # will cleanly finish. @@ -167,18 +167,21 @@ def prepare_build( ).count() > 1 if not project.has_feature(Feature.DEDUPLICATE_BUILDS): - log.debug('Skipping deduplication of builds. Feature not enabled. project=%s', project.slug) + log.debug( + 'Skipping deduplication of builds. Feature not enabled.', + project_slug=project.slug, + ) skip_build = False if skip_build: # TODO: we could mark the old build as duplicated, however we reset our # position in the queue and go back to the end of it --penalization log.warning( - 'Marking build to be skipped by builder. project=%s version=%s build=%s commit=%s', - project.slug, - version.slug, - build.pk, - commit, + 'Marking build to be skipped by builder.', + project_slug=project.slug, + version_slug=version.slug, + build_id=build.pk, + commit=commit, ) build.error = DuplicatedBuildError.message build.status = DuplicatedBuildError.status @@ -192,9 +195,9 @@ def prepare_build( limit_reached, _, max_concurrent_builds = Build.objects.concurrent(project) if limit_reached: log.warning( - 'Delaying tasks at trigger step due to concurrency limit. project=%s version=%s', - project.slug, - version.slug, + 'Delaying tasks at trigger step due to concurrency limit.', + project_slug=project.slug, + version_slug=version.slug, ) options['countdown'] = 5 * 60 options['max_retries'] = 25 @@ -230,10 +233,10 @@ def trigger_build(project, version=None, commit=None, record=True, force=False): :rtype: tuple """ log.info( - 'Triggering build. project=%s version=%s commit=%s', - project.slug, - version.slug if version else None, - commit, + 'Triggering build.', + project_slug=project.slug, + version_slug=version.slug if version else None, + commit=commit, ) update_docs_task, build = prepare_build( project=project, diff --git a/readthedocs/core/utils/contact.py b/readthedocs/core/utils/contact.py index 13a2ac0d007..46cd26d7a23 100644 --- a/readthedocs/core/utils/contact.py +++ b/readthedocs/core/utils/contact.py @@ -1,4 +1,4 @@ -import logging +import structlog from pprint import pprint import markdown @@ -10,7 +10,7 @@ from readthedocs.notifications import SiteNotification from readthedocs.notifications.backends import SiteBackend -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def contact_users( @@ -101,8 +101,10 @@ def render(self, *args, **kwargs): failed_notifications.add(user.username) else: log.info( - 'Successfully set notification (%s/%s). user=%s', - count, total, user, + 'Successfully set notification.', + user_username=user.username, + count=count, + total=total, ) sent_notifications.add(user.username) @@ -145,7 +147,7 @@ def render(self, *args, **kwargs): log.exception('Email failed to send') failed_emails.update(emails) else: - log.info('Email sent (%s/%s). emails=%s', count, total, emails) + log.info('Email sent.', emails=emails, count=count, total=total) sent_emails.update(emails) return { diff --git a/readthedocs/core/views/__init__.py b/readthedocs/core/views/__init__.py index 32a6e3acf20..493b74d7bdb 100644 --- a/readthedocs/core/views/__init__.py +++ b/readthedocs/core/views/__init__.py @@ -5,7 +5,7 @@ and server errors. """ -import logging +import structlog from django.conf import settings from django.http import Http404, JsonResponse @@ -17,7 +17,7 @@ from readthedocs.core.mixins import PrivateViewMixin from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class NoProjectException(Exception): diff --git a/readthedocs/core/views/hooks.py b/readthedocs/core/views/hooks.py index 99ab4ce4c59..700cf89b573 100644 --- a/readthedocs/core/views/hooks.py +++ b/readthedocs/core/views/hooks.py @@ -1,13 +1,13 @@ """Views pertaining to builds.""" -import logging +import structlog from readthedocs.builds.constants import EXTERNAL from readthedocs.core.utils import trigger_build from readthedocs.projects.models import Feature, Project from readthedocs.projects.tasks import sync_repository_task -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def _build_version(project, slug, already_built=()): @@ -25,14 +25,14 @@ def _build_version(project, slug, already_built=()): version = project.versions.filter(active=True, slug=slug).first() if version and slug not in already_built: log.info( - '(Version build) Building %s:%s', - project.slug, - version.slug, + 'Building.', + project_slug=project.slug, + version_slug=version.slug, ) trigger_build(project=project, version=version, force=True) return slug - log.info('(Version build) Not Building %s', slug) + log.info('Not building.', version_slug=slug) return None @@ -51,9 +51,9 @@ def build_branches(project, branch_list): for version in versions: log.info( - '(Branch Build) Processing %s:%s', - project.slug, - version.slug, + 'Processing.', + project_slug=project.slug, + version_slug=version.slug, ) ret = _build_version(project, version.slug, already_built=to_build) if ret: @@ -78,8 +78,8 @@ def trigger_sync_versions(project): if not Project.objects.is_active(project): log.warning( - 'Sync not triggered because Project is not active: project=%s', - project.slug, + 'Sync not triggered because project is not active.', + project_slug=project.slug, ) return None @@ -91,11 +91,11 @@ def trigger_sync_versions(project): ).first() ) if not version: - log.info('Unable to sync from %s version', version_identifier) + log.info('Unable to sync from version.', version_identifier=version_identifier) return None if project.has_feature(Feature.SKIP_SYNC_VERSIONS): - log.info('Skipping sync versions for project: project=%s', project.slug) + log.info('Skipping sync versions for project.', project_slug=project.slug) return None options = {} @@ -104,9 +104,9 @@ def trigger_sync_versions(project): options['queue'] = project.build_queue log.info( - 'Triggering sync repository. project=%s version=%s', - version.project.slug, - version.slug, + 'Triggering sync repository.', + project_slug=version.project.slug, + version_slug=version.slug, ) sync_repository_task.apply_async( (version.pk,), @@ -138,8 +138,9 @@ def get_or_create_external_version(project, identifier, verbose_name): if created: log.info( - 'External version created. project=%s version=%s', - project.slug, external_version.slug, + 'External version created.', + project_slug=project.slug, + version_slug=external_version.slug, ) else: # Identifier will change if there is a new commit to the Pull/Merge Request. @@ -149,8 +150,9 @@ def get_or_create_external_version(project, identifier, verbose_name): external_version.save() log.info( - 'External version updated: project=%s version=%s', - project.slug, external_version.slug, + 'External version updated.', + project_slug=project.slug, + version_slug=external_version.slug, ) return external_version @@ -178,8 +180,9 @@ def deactivate_external_version(project, identifier, verbose_name): external_version.active = False external_version.save() log.info( - 'External version marked as inactive. project=%s version=%s', - project.slug, external_version.slug, + 'External version marked as inactive.', + project_slug=project.slug, + version_slug=external_version.slug, ) return external_version.verbose_name return None @@ -197,9 +200,9 @@ def build_external_version(project, version, commit): # Build External version log.info( - '(External Version build) Building %s:%s', - project.slug, - version.slug, + 'Building external version', + project_slug=project.slug, + version_slug=version.slug, ) trigger_build(project=project, version=version, commit=commit, force=True) diff --git a/readthedocs/doc_builder/backends/mkdocs.py b/readthedocs/doc_builder/backends/mkdocs.py index 76659812c30..3298d3f80dc 100644 --- a/readthedocs/doc_builder/backends/mkdocs.py +++ b/readthedocs/doc_builder/backends/mkdocs.py @@ -4,7 +4,7 @@ .. _MkDocs: http://www.mkdocs.org/ """ -import logging +import structlog import os import yaml @@ -16,7 +16,7 @@ from readthedocs.projects.constants import MKDOCS, MKDOCS_HTML from readthedocs.projects.models import Feature -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def get_absolute_static_url(): @@ -59,8 +59,8 @@ def __init__(self, *args, **kwargs): if self.project.has_feature(Feature.MKDOCS_THEME_RTD): self.DEFAULT_THEME_NAME = 'readthedocs' log.warning( - 'Project using readthedocs theme as default for MkDocs: slug=%s', - self.project.slug, + 'Project using readthedocs theme as default for MkDocs.', + project_slug=self.project.slug, ) else: self.DEFAULT_THEME_NAME = 'mkdocs' @@ -107,9 +107,9 @@ def load_yaml_config(self): except IOError: log.info( - 'Creating default MkDocs config file for project: %s:%s', - self.project.slug, - self.version.slug, + 'Creating default MkDocs config file for project.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) return { 'site_name': self.version.project.name, diff --git a/readthedocs/doc_builder/backends/sphinx.py b/readthedocs/doc_builder/backends/sphinx.py index c315420b942..21ef49f01ba 100644 --- a/readthedocs/doc_builder/backends/sphinx.py +++ b/readthedocs/doc_builder/backends/sphinx.py @@ -5,7 +5,7 @@ """ import codecs import itertools -import logging +import structlog import os import shutil import zipfile @@ -31,7 +31,7 @@ from ..exceptions import BuildEnvironmentError from ..signals import finalize_sphinx_context_data -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BaseSphinx(BaseBuilder): @@ -63,9 +63,9 @@ def __init__(self, *args, **kwargs): def _write_config(self, master_doc='index'): """Create ``conf.py`` if it doesn't exist.""" log.info( - 'Creating default Sphinx config file for project: %s:%s', - self.project.slug, - self.version.slug, + 'Creating default Sphinx config file for project.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) docs_dir = self.docs_dir() conf_template = render_to_string( @@ -138,9 +138,9 @@ def get_config_params(self): subproject_urls = self.project.get_subproject_urls() except ConnectionError: log.exception( - 'Timeout while fetching versions/downloads/subproject_urls for Sphinx context. ' - 'project: %s version: %s', - self.project.slug, self.version.slug, + 'Timeout while fetching versions/downloads/subproject_urls for Sphinx context.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) build_id = self.build_env.build.get('id') @@ -391,7 +391,7 @@ class LocalMediaBuilder(BaseSphinx): @restoring_chdir def move(self, **__): - log.info('Creating zip file from %s', self.old_artifact_path) + log.info('Creating zip file from path.', path=self.old_artifact_path) target_file = os.path.join( self.target, '{}.zip'.format(self.project.slug), diff --git a/readthedocs/doc_builder/base.py b/readthedocs/doc_builder/base.py index c3406d80efc..d16c9584dd0 100644 --- a/readthedocs/doc_builder/base.py +++ b/readthedocs/doc_builder/base.py @@ -1,6 +1,6 @@ """Base classes for Builders.""" -import logging +import structlog import os import shutil from functools import wraps @@ -8,7 +8,7 @@ from readthedocs.projects.models import Feature -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def restoring_chdir(fn): @@ -73,8 +73,8 @@ def move(self, **__): if os.path.exists(self.old_artifact_path): if os.path.exists(self.target): shutil.rmtree(self.target) - log.info('Copying %s on the local filesystem', self.type) - log.debug('Ignoring patterns %s', self.ignore_patterns) + log.info('Copying output type on the local filesystem.', output_type=self.type) + log.debug('Ignoring patterns.', patterns=self.ignore_patterns) shutil.copytree( self.old_artifact_path, self.target, @@ -87,7 +87,7 @@ def clean(self, **__): """Clean the path where documentation will be built.""" if os.path.exists(self.old_artifact_path): shutil.rmtree(self.old_artifact_path) - log.info('Removing old artifact path: %s', self.old_artifact_path) + log.info('Removing old artifact path.', path=self.old_artifact_path) def docs_dir(self, docs_dir=None, **__): """Handle creating a custom docs_dir if it doesn't exist.""" diff --git a/readthedocs/doc_builder/constants.py b/readthedocs/doc_builder/constants.py index db019d8872e..50898dbc1ec 100644 --- a/readthedocs/doc_builder/constants.py +++ b/readthedocs/doc_builder/constants.py @@ -2,13 +2,13 @@ """Doc build constants.""" -import logging +import structlog import re from django.conf import settings -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) PDF_RE = re.compile('Output written on (.*?)') diff --git a/readthedocs/doc_builder/environments.py b/readthedocs/doc_builder/environments.py index 0d0a75bc73b..49cd84c5167 100644 --- a/readthedocs/doc_builder/environments.py +++ b/readthedocs/doc_builder/environments.py @@ -1,6 +1,6 @@ """Documentation Builder Environments.""" -import logging +import structlog import os import re import socket @@ -23,7 +23,6 @@ from readthedocs.builds.constants import BUILD_STATE_FINISHED from readthedocs.builds.models import BuildCommandResultMixin from readthedocs.core.utils import slugify -from readthedocs.projects.constants import LOG_TEMPLATE from readthedocs.projects.exceptions import ( ProjectConfigurationError, RepositoryError, @@ -51,7 +50,7 @@ YAMLParseError, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) __all__ = ( 'api_v2', @@ -129,7 +128,7 @@ def __str__(self): def run(self): """Set up subprocess and execute command.""" - log.info("Running: '%s' [%s]", self.get_command(), self.cwd) + log.info("Running build command.", command=self.get_command(), cwd=self.cwd) self.start_time = datetime.utcnow() environment = self._environment.copy() @@ -202,11 +201,11 @@ def sanitize_output(self, output): allowed_length = settings.DATA_UPLOAD_MAX_MEMORY_SIZE - threshold if output_length > allowed_length: log.info( - 'Command output is too big: project=[%s] version=[%s] build=[%s] command=[%s]', # noqa - self.build_env.project.slug, - self.build_env.version.slug, - self.build_env.build.get('id'), - self.get_command(), + 'Command output is too big.', + project_slug=self.build_env.project.slug, + version_slug=self.build_env.version.slug, + build_id=self.build_env.build.get('id'), + command=self.get_command(), ) truncated_output = sanitized[-allowed_length:] sanitized = ( @@ -256,10 +255,10 @@ def save(self): 'Content-Type': encoder.content_type, } ) - log.debug('Post response via multipart form: %s', resp) + log.debug('Post response via multipart form.', response=resp) else: resp = api_v2.command.post(data) - log.debug('Post response via JSON encoded data: %s', resp) + log.debug('Post response via JSON encoded data.', response=resp) class DockerBuildCommand(BuildCommand): @@ -290,10 +289,10 @@ def __init__(self, *args, escape_command=True, **kwargs): def run(self): """Execute command in existing Docker container.""" log.info( - "Running in container %s: '%s' [%s]", - self.build_env.container_id, - self.get_command(), - self.cwd, + "Running build command in container.", + container_id=self.build_env.container_id, + command=self.get_command(), + cwd=self.cwd, ) self.start_time = datetime.utcnow() @@ -456,12 +455,9 @@ def run_command_class( if warn_only: log.warning( - LOG_TEMPLATE, - { - 'project': self.project.slug if self.project else '', - 'version': 'latest', - 'msg': msg, - } + msg, + project_slug=self.project.slug if self.project else '', + version_slug=self.version.slug if self.version else '', ) else: raise BuildEnvironmentWarning(msg) @@ -549,12 +545,9 @@ def __exit__(self, exc_type, exc_value, tb): ret = self.handle_exception(exc_type, exc_value, tb) self.update_build(BUILD_STATE_FINISHED) log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug if self.project else '', - 'version': self.version.slug if self.version else '', - 'msg': 'Build finished', - } + 'Build finished', + project_slug=self.project.slug if self.project else '', + version_slug=self.version.slug if self.version else '', ) return ret @@ -585,12 +578,9 @@ def handle_exception(self, exc_type, exc_value, _): self.failure = exc_value log_level_function( - LOG_TEMPLATE, - { - 'project': self.project.slug if self.project else '', - 'version': self.version.slug if self.version else '', - 'msg': exc_value, - }, + msg=exc_value, + project_slug=self.project.slug if self.project else '', + version_slug=self.version.slug if self.version else '', exc_info=True, extra={ 'stack': True, @@ -698,8 +688,8 @@ def update_build(self, state=None): ): # yapf: enable log.error( - 'Build failed with unhandled exception: %s', - str(self.failure), + 'Build failed with unhandled exception.', + exception=str(self.failure), extra={ 'stack': True, 'tags': { @@ -735,8 +725,8 @@ def update_build(self, state=None): api_v2.build(self.build['id']).put(self.build) except HttpClientError: log.exception( - 'Unable to update build: id=%d', - self.build['id'], + 'Unable to update build', + build_id=self.build['id'], ) except Exception: log.exception('Unknown build exception') @@ -815,16 +805,10 @@ def __enter__(self): raise exc log.warning( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': ( - 'Removing stale container {}'.format( - self.container_id, - ) - ), - } + 'Removing stale container.', + project=self.project.slug, + version=self.version.slug, + container_id=self.container_id, ) client = self.get_client() client.remove_container(self.container_id) @@ -860,33 +844,30 @@ def __exit__(self, exc_type, exc_value, tb): client.kill(self.container_id) except DockerNotFoundError: log.info( - 'Container does not exists, nothing to kill. id=%s', - self.container_id, + 'Container does not exists, nothing to kill.', + container_id=self.container_id, ) except DockerAPIError: log.exception( - 'Unable to kill container: id=%s', - self.container_id, + 'Unable to kill container.', + container_id=self.container_id, ) try: - log.info('Removing container: id=%s', self.container_id) + log.info('Removing container.', container_id=self.container_id) client.remove_container(self.container_id) except DockerNotFoundError: log.info( - 'Container does not exists, nothing to remove. id=%s', - self.container_id, + 'Container does not exists, nothing to remove.', + container_id=self.container_id, ) # Catch direct failures from Docker API or with an HTTP request. # These errors should not surface to the user. except (DockerAPIError, ConnectionError, ReadTimeout): log.exception( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': "Couldn't remove container", - } + "Couldn't remove container", + project=self.project.slug, + version=self.version.slug, ) self.container = None except BuildEnvironmentError: @@ -923,12 +904,9 @@ def get_client(self): return self.client except DockerException: log.exception( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': "Could not connect to Docker API", - } + "Could not connect to Docker API", + project_slug=self.project.slug, + version_slug=self.version.slug, ) # We don't raise an error here mentioning Docker, that is a # technical detail that the user can't resolve on their own. @@ -1039,9 +1017,9 @@ def create_container(self): client = self.get_client() try: log.info( - 'Creating Docker container: image=%s id=%s', - self.container_image, - self.container_id, + 'Creating Docker container.', + container_image=self.container_image, + container_id=self.container_id, ) self.container = client.create_container( image=self.container_image, @@ -1060,15 +1038,9 @@ def create_container(self): client.start(container=self.container_id) except ConnectionError: log.exception( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': ( - 'Could not connect to the Docker API, ' - 'make sure Docker is running' - ), - } + 'Could not connect to the Docker API, make sure Docker is running.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) # We don't raise an error here mentioning Docker, that is a # technical detail that the user can't resolve on their own. @@ -1080,11 +1052,8 @@ def create_container(self): ) except DockerAPIError as e: log.exception( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': e.explanation, - } + e.explanation, + project_slug=self.project.slug, + version_slug=self.version.slug, ) raise BuildEnvironmentCreationFailed diff --git a/readthedocs/doc_builder/python_environments.py b/readthedocs/doc_builder/python_environments.py index 911ccb3e99c..3bfc0ebbff3 100644 --- a/readthedocs/doc_builder/python_environments.py +++ b/readthedocs/doc_builder/python_environments.py @@ -5,7 +5,7 @@ import hashlib import itertools import json -import logging +import structlog import os import shutil import tarfile @@ -21,11 +21,10 @@ from readthedocs.doc_builder.constants import DOCKER_IMAGE from readthedocs.doc_builder.environments import DockerBuildEnvironment from readthedocs.doc_builder.loader import get_builder_class -from readthedocs.projects.constants import LOG_TEMPLATE from readthedocs.projects.models import Feature from readthedocs.storage import build_tools_storage -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class PythonEnvironment: @@ -51,12 +50,9 @@ def delete_existing_build_dir(self): ) if os.path.exists(build_dir): log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': 'Removing existing build directory', - } + 'Removing existing build directory', + project_slug=self.project.slug, + version_slug=self.version.slug, ) shutil.rmtree(build_dir) @@ -65,12 +61,9 @@ def delete_existing_venv_dir(self): # Handle deleting old venv dir if os.path.exists(venv_dir): log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': 'Removing existing venv directory', - } + 'Removing existing venv directory', + project_slug=self.project.slug, + version_slug=self.version.slug, ) shutil.rmtree(venv_dir) @@ -131,11 +124,11 @@ def install_build_tools(self): ) else: log.debug( - 'Cached version for tool not found. os=%s tool=%s version=% filename=%s', - self.config.build.os, - tool, - full_version, - tool_path, + 'Cached version for tool not found.', + os=self.config.build.os, + tool=tool, + full_version=full_version, + tool_path=tool_path, ) # If the tool version selected is not available from the # cache we compile it at build time @@ -677,12 +670,9 @@ def setup_base(self): if os.path.exists(version_path): # Re-create conda directory each time to keep fresh state log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': 'Removing existing conda directory', - }, + 'Removing existing conda directory', + project_slug=self.project.slug, + version_slug=self.version.slug, ) shutil.rmtree(version_path) diff --git a/readthedocs/embed/v3/views.py b/readthedocs/embed/v3/views.py index ebe51c61e69..3c962448a9a 100644 --- a/readthedocs/embed/v3/views.py +++ b/readthedocs/embed/v3/views.py @@ -66,7 +66,7 @@ def _download_page_content(self, url): cache_key = f'embed-api-{url}' cached_response = cache.get(cache_key) if cached_response: - log.debug('Cached response. url=%s', url) + log.debug('Cached response.', url=url) return cached_response response = requests.get(url, timeout=settings.RTD_EMBED_API_DEFAULT_REQUEST_TIMEOUT) @@ -103,7 +103,7 @@ def _get_page_content_from_storage(self, project, version_slug, filename): with build_media_storage.open(file_path) as fd: # pylint: disable=invalid-name return fd.read() except Exception: # noqa - log.warning('Unable to read file. file_path=%s', file_path) + log.warning('Unable to read file.', file_path=file_path) return None @@ -248,7 +248,7 @@ def get(self, request): # noqa if re.match(allowed_domain, domain): break else: - log.info('Domain not allowed. domain=%s url=%s', domain, url) + log.info('Domain not allowed.', domain=domain, url=url) return Response( { 'error': ( @@ -264,7 +264,7 @@ def get(self, request): # noqa cache.get_or_set(cache_key, 0, timeout=settings.RTD_EMBED_API_DOMAIN_RATE_LIMIT_TIMEOUT) cache.incr(cache_key) if cache.get(cache_key) > settings.RTD_EMBED_API_DOMAIN_RATE_LIMIT: - log.warning('Too many requests for this domain. domain=%s', domain) + log.warning('Too many requests for this domain.', domain=domain) return Response( { 'error': ( @@ -289,7 +289,7 @@ def get(self, request): # noqa doctoolversion, ) except requests.exceptions.TooManyRedirects: - log.exception('Too many redirects. url=%s', url) + log.exception('Too many redirects.', url=url) return Response( { 'error': ( @@ -304,7 +304,7 @@ def get(self, request): # noqa status=status.HTTP_400_BAD_REQUEST, ) except Exception: # noqa - log.exception('There was an error reading the URL requested. url=%s', url) + log.exception('There was an error reading the URL requested.', url=url) return Response( { 'error': ( @@ -316,7 +316,7 @@ def get(self, request): # noqa ) if not content_requested: - log.warning('Identifier not found. url=%s fragment=%s', url, fragment) + log.warning('Identifier not found.', url=url, fragment=fragment) return Response( { 'error': ( diff --git a/readthedocs/embed/views.py b/readthedocs/embed/views.py index 76e2e69639f..4e23d783751 100644 --- a/readthedocs/embed/views.py +++ b/readthedocs/embed/views.py @@ -233,7 +233,7 @@ def _get_doc_content(project, version, doc): with build_media_storage.open(file_path) as file: return json.load(file) except Exception: # noqa - log.warning('Unable to read file. file_path=%s', file_path) + log.warning('Unable to read file.', file_path=file_path) return None @@ -279,8 +279,9 @@ def parse_sphinx(content, section, url): break except Exception: # noqa log.info( - 'Failed to query section. url=%s id=%s', - url, element_id, + 'Failed to query section.', + url=url, + element_id=element_id, ) if not query_result: diff --git a/readthedocs/forms.py b/readthedocs/forms.py index 228c4d21ba0..499886aeed6 100644 --- a/readthedocs/forms.py +++ b/readthedocs/forms.py @@ -1,6 +1,6 @@ """Community site-wide form overrides.""" -import logging +import structlog import requests @@ -8,7 +8,7 @@ from django.conf import settings from django import forms -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa class SignupFormWithNewsletter(SignupForm): @@ -34,11 +34,11 @@ def save(self, request): user = super().save(request) if self.cleaned_data.get("receive_newsletter"): - log.info( - 'Subscribing user to newsletter. email=%s, user=%s', - self.cleaned_data["email"], - user.username, + log.bind( + user_email=self.cleaned_data["email"], + user_username=user.username, ) + log.info('Subscribing user to newsletter.') url = settings.MAILERLITE_API_SUBSCRIBERS_URL payload = { @@ -57,16 +57,8 @@ def save(self, request): ) resp.raise_for_status() except requests.Timeout: - log.warning( - 'Timeout subscribing user to newsletter. email=%s, user=%s', - self.cleaned_data["email"], - user.username, - ) + log.warning('Timeout subscribing user to newsletter.') except Exception: # noqa - log.exception( - 'Unknown error subscribing user to newsletter. email=%s, user=%s', - self.cleaned_data["email"], - user.username, - ) + log.exception('Unknown error subscribing user to newsletter.') return user diff --git a/readthedocs/gold/views.py b/readthedocs/gold/views.py index d27a2b64dab..43d17f135bd 100644 --- a/readthedocs/gold/views.py +++ b/readthedocs/gold/views.py @@ -3,7 +3,7 @@ """Gold subscription views.""" import json -import logging +import structlog import stripe from django.conf import settings @@ -29,7 +29,7 @@ from .models import GoldUser, LEVEL_CHOICES -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class GoldSubscription( @@ -137,7 +137,7 @@ def post(self, request, *args, **kwargs): url = reverse_lazy('gold_detail') url = f'{schema}://{settings.PRODUCTION_DOMAIN}{url}' price = json.loads(request.body).get('priceId') - log.info('Creating Stripe Checkout Session. user=%s price=%s', user, price) + log.info('Creating Stripe Checkout Session.', user_username=user.username, price=price) checkout_session = stripe.checkout.Session.create( client_reference_id=user.username, customer_email=user.emailaddress_set.filter(verified=True).first() or user.email, @@ -184,9 +184,9 @@ def post(self, request, *args, **kwargs): return HttpResponseRedirect(billing_portal.url) except: # noqa log.exception( - 'There was an error connecting to Stripe. user=%s stripe_customer=%s', - user.username, - stripe_customer, + 'There was an error connecting to Stripe.', + user_userame=user.username, + stripe_customer=stripe_customer, ) messages.error( request, @@ -223,7 +223,7 @@ def post(self, request, format=None): try: event = stripe.Event.construct_from(request.data, settings.STRIPE_SECRET) if event.type not in self.EVENTS: - log.warning('Unhandled Stripe event. event=%s', event.type) + log.warning('Unhandled Stripe event.', event_type=event.type) return Response({ 'OK': False, 'msg': f'Unhandled event. event={event.type}' @@ -268,18 +268,18 @@ def post(self, request, format=None): username = event.data.object.client_reference_id # TODO: add user notification saying it failed log.exception( - 'Gold User payment failed. username=%s customer=%s', - username, - stripe_customer, + 'Gold User payment failed.', + user_username=username, + stripe_customer=stripe_customer, ) elif event.type == self.EVENT_CUSTOMER_SUBSCRIPTION_UPDATED: subscription = event.data.object level = subscription.plan.id log.info( - 'Gold User subscription updated. customer=%s level=%s', - stripe_customer, - level, + 'Gold User subscription updated.', + stripe_customer=stripe_customer, + level=level, ) ( GoldUser.objects @@ -294,9 +294,8 @@ def post(self, request, format=None): # TODO: check if the subscription was canceled, past due, etc # and take the according action. Only acummulate errors on Sentry for now. log.error( - 'GoldUser is not active anymore. ' - 'stripe_customer=%s', - stripe_customer, + 'GoldUser is not active anymore.', + stripe_customer=stripe_customer, ) except Exception: log.exception('Unexpected data in Stripe Event object') diff --git a/readthedocs/notifications/notification.py b/readthedocs/notifications/notification.py index 592fdf1c73a..30a99a79b1b 100644 --- a/readthedocs/notifications/notification.py +++ b/readthedocs/notifications/notification.py @@ -2,7 +2,7 @@ """Support for templating of notifications.""" -import logging +import structlog from readthedocs.core.context_processors import readthedocs_processor from django.conf import settings @@ -15,7 +15,7 @@ from .backends import send_notification -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Notification: @@ -172,16 +172,16 @@ def get_message(self, success): else: # log the error but not crash log.error( - "Notification %s has no key '%s' for %s messages", - self.__class__.__name__, - self.reason, - 'success' if self.success else 'failure', + "Notification has no key for messages", + notification=self.__class__.__name__, + key=self.reason, + message='success' if self.success else 'failure', ) else: log.error( - '%s.%s_message is a dictionary but no reason was provided', - self.__class__.__name__, - 'success' if self.success else 'failure', + '{message} is a dictionary but no reason was provided', + notification=self.__class__.__name__, + message='success' if self.success else 'failure', ) else: msg = message diff --git a/readthedocs/oauth/migrations/0003_move_github.py b/readthedocs/oauth/migrations/0003_move_github.py index 2b4837f4e1a..535fdaef51b 100644 --- a/readthedocs/oauth/migrations/0003_move_github.py +++ b/readthedocs/oauth/migrations/0003_move_github.py @@ -1,12 +1,12 @@ # -*- coding: utf-8 -*- import gc import json -import logging +import structlog from django.db import migrations -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def chunks(queryset, chunksize=1000): @@ -50,7 +50,7 @@ def forwards_move_repos(apps, schema_editor): except: pass new_org.save() - log.info('Migrated organization: %s', org.name) + log.info('Migrated organization.', organization_slug=org.slug) for org in chunks(BitbucketTeam.objects.all()): new_org = RemoteOrganization.objects.using(db).create( @@ -70,7 +70,7 @@ def forwards_move_repos(apps, schema_editor): except: pass new_org.save() - log.info('Migrated organization: %s', org.name) + log.info('Migrated organization.', organization_slug=org.slug) # Now repositories GithubProject = apps.get_model('oauth', 'GithubProject') @@ -110,7 +110,7 @@ def forwards_move_repos(apps, schema_editor): except (SyntaxError, ValueError): pass new_repo.save() - log.info('Migrated project: %s', project.name) + log.info('Migrated project.', project_slug=project.slug) for project in chunks(BitbucketProject.objects.all()): new_repo = RemoteRepository.objects.using(db).create( @@ -151,7 +151,7 @@ def forwards_move_repos(apps, schema_editor): except (SyntaxError, ValueError): pass new_repo.save() - log.info('Migrated project: %s', project.name) + log.info('Migrated project.', project_slug=project.slug) def reverse_move_repos(apps, schema_editor): diff --git a/readthedocs/oauth/services/base.py b/readthedocs/oauth/services/base.py index a8c6ac1ee68..fa96cd3d358 100644 --- a/readthedocs/oauth/services/base.py +++ b/readthedocs/oauth/services/base.py @@ -1,6 +1,6 @@ """OAuth utility functions.""" -import logging +import structlog from datetime import datetime from allauth.socialaccount.models import SocialAccount @@ -17,7 +17,7 @@ ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class SyncServiceError(Exception): @@ -134,7 +134,7 @@ def _updater(data): datetime.fromtimestamp(data['expires_at']), ) token.save() - log.info('Updated token %s:', token) + log.info('Updated token.', token=token) return _updater @@ -173,7 +173,7 @@ def paginate(self, url, **kwargs): return results # Catch specific exception related to OAuth except InvalidClientIdError: - log.warning('access_token or refresh_token failed: %s', url) + log.warning('access_token or refresh_token failed.', url=url) raise Exception('You should reconnect your account') # Catch exceptions with request or deserializing JSON except (RequestException, ValueError): @@ -184,9 +184,9 @@ def paginate(self, url, **kwargs): except ValueError: debug_data = resp.content log.debug( - 'Paginate failed at %s with response: %s', - url, - debug_data, + 'Paginate failed at URL.', + url=url, + debug_data=debug_data, ) return [] diff --git a/readthedocs/oauth/services/bitbucket.py b/readthedocs/oauth/services/bitbucket.py index 119f386fc29..22a298e2b82 100644 --- a/readthedocs/oauth/services/bitbucket.py +++ b/readthedocs/oauth/services/bitbucket.py @@ -1,7 +1,7 @@ """OAuth utility functions.""" import json -import logging +import structlog import re from allauth.socialaccount.providers.bitbucket_oauth2.views import ( @@ -23,7 +23,7 @@ from .base import Service, SyncServiceError -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BitbucketService(Service): @@ -142,8 +142,8 @@ def create_repository(self, fields, privacy=None, organization=None): if repo.organization and repo.organization != organization: log.debug( - 'Not importing %s because mismatched orgs', - fields['name'], + 'Not importing repository because mismatched orgs.', + repository=fields['name'], ) return None @@ -181,8 +181,8 @@ def create_repository(self, fields, privacy=None, organization=None): return repo log.debug( - 'Not importing %s because mismatched type', - fields['name'], + 'Not importing repository because mismatched type.', + repository=fields['name'], ) def create_organization(self, fields): @@ -286,21 +286,20 @@ def get_provider_data(self, project, integration): integration.save() log.info( - 'Bitbucket integration updated with provider data for project: %s', - project, + 'Bitbucket integration updated with provider data for project.', + project_slug=project.slug, ) break else: log.info( - 'Bitbucket project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'Bitbucket project does not exist or user does not have permissions.', + project_slug=project.slug, ) except Exception: log.exception( - 'Bitbucket webhook Listing failed for project: %s', - project, + 'Bitbucket webhook Listing failed for project.', + project_slug=project.slug, ) return integration.provider_data @@ -340,33 +339,32 @@ def setup_webhook(self, project, integration=None): integration.provider_data = recv_data integration.save() log.info( - 'Bitbucket webhook creation successful for project: %s', - project, + 'Bitbucket webhook creation successful for project.', + project_slug=project.slug, ) return (True, resp) if resp.status_code in [401, 403, 404]: log.info( - 'Bitbucket project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'Bitbucket project does not exist or user does not have permissions.', + project_slug=project.slug, ) # Catch exceptions with request or deserializing JSON except (RequestException, ValueError): log.exception( - 'Bitbucket webhook creation failed for project: %s', - project, + 'Bitbucket webhook creation failed for project.', + project_slug=project.slug, ) else: log.error( - 'Bitbucket webhook creation failed for project: %s', - project, + 'Bitbucket webhook creation failed for project.', + project_slug=project.slug, ) try: log.debug( - 'Bitbucket webhook creation failure response: %s', - resp.json(), + 'Bitbucket webhook creation failure response.', + response=resp.json(), ) except ValueError: pass @@ -408,8 +406,8 @@ def update_webhook(self, project, integration): integration.provider_data = recv_data integration.save() log.info( - 'Bitbucket webhook update successful for project: %s', - project, + 'Bitbucket webhook update successful for project.', + project_slug=project.slug, ) return (True, resp) @@ -421,13 +419,13 @@ def update_webhook(self, project, integration): # Catch exceptions with request or deserializing JSON except (KeyError, RequestException, TypeError, ValueError): log.exception( - 'Bitbucket webhook update failed for project: %s', - project, + 'Bitbucket webhook update failed for project.', + project_slug=project.slug, ) else: log.error( - 'Bitbucket webhook update failed for project: %s', - project, + 'Bitbucket webhook update failed for project.', + project_slug=project.slug, ) # Response data should always be JSON, still try to log if not though try: @@ -435,8 +433,8 @@ def update_webhook(self, project, integration): except ValueError: debug_data = resp.content log.debug( - 'Bitbucket webhook update failure response: %s', - debug_data, + 'Bitbucket webhook update failure response.', + debug_data=debug_data, ) return (False, resp) diff --git a/readthedocs/oauth/services/github.py b/readthedocs/oauth/services/github.py index 366a3794092..bd0bc991f12 100644 --- a/readthedocs/oauth/services/github.py +++ b/readthedocs/oauth/services/github.py @@ -1,7 +1,7 @@ """OAuth utility functions.""" import json -import logging +import structlog import re from allauth.socialaccount.models import SocialToken @@ -23,7 +23,7 @@ from ..models import RemoteOrganization, RemoteRepository from .base import Service, SyncServiceError -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class GitHubService(Service): @@ -119,8 +119,8 @@ def create_repository(self, fields, privacy=None, organization=None): # creation of the ``RemoteRepositoryRelation``. if repo.organization and organization and repo.organization != organization: log.debug( - 'Not importing %s because mismatched orgs', - fields['name'], + 'Not importing repository because mismatched orgs.', + repository=fields['name'], ) return None @@ -160,8 +160,8 @@ def create_repository(self, fields, privacy=None, organization=None): return repo log.debug( - 'Not importing %s because mismatched type', - fields['name'], + 'Not importing repository because mismatched type.', + repository=fields['name'], ) def create_organization(self, fields): @@ -267,21 +267,20 @@ def get_provider_data(self, project, integration): integration.save() log.info( - 'GitHub integration updated with provider data for project: %s', - project, + 'GitHub integration updated with provider data for project.', + project_slug=project.slug, ) break else: log.info( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'GitHub project does not exist or user does not have permissions.', + project_slug=project.slug, ) except Exception: log.exception( - 'GitHub webhook Listing failed for project: %s', - project, + 'GitHub webhook Listing failed for project.', + project_slug=project.slug, ) return integration.provider_data @@ -327,16 +326,15 @@ def setup_webhook(self, project, integration=None): integration.provider_data = recv_data integration.save() log.info( - 'GitHub webhook creation successful for project: %s', - project, + 'GitHub webhook creation successful for project.', + project_slug=project.slug, ) return (True, resp) if resp.status_code in [401, 403, 404]: log.info( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'GitHub project does not exist or user does not have permissions.', + project_slug=project.slug, ) # All other status codes will flow to the `else` clause below @@ -344,13 +342,13 @@ def setup_webhook(self, project, integration=None): # Catch exceptions with request or deserializing JSON except (RequestException, ValueError): log.exception( - 'GitHub webhook creation failed for project: %s', - project, + 'GitHub webhook creation failed for project.', + project_slug=project.slug, ) else: log.error( - 'GitHub webhook creation failed for project: %s', - project, + 'GitHub webhook creation failed for project.', + project_slug=project.slug, ) # Response data should always be JSON, still try to log if not # though @@ -359,8 +357,8 @@ def setup_webhook(self, project, integration=None): except ValueError: debug_data = resp.content log.debug( - 'GitHub webhook creation failure response: %s', - debug_data, + 'GitHub webhook creation failure response.', + debug_data=debug_data, ) # Always remove the secret and return False if we don't return True above @@ -406,8 +404,8 @@ def update_webhook(self, project, integration): integration.provider_data = recv_data integration.save() log.info( - 'GitHub webhook update successful for project: %s', - project, + 'GitHub webhook update successful for project.', + project_slug=project.slug, ) return (True, resp) @@ -419,21 +417,21 @@ def update_webhook(self, project, integration): # Catch exceptions with request or deserializing JSON except (AttributeError, RequestException, ValueError): log.exception( - 'GitHub webhook update failed for project: %s', - project, + 'GitHub webhook update failed for project.', + project_slug=project.slug, ) else: log.error( - 'GitHub webhook update failed for project: %s', - project, + 'GitHub webhook update failed for project.', + project_slug=project.slug, ) try: debug_data = resp.json() except ValueError: debug_data = resp.content log.debug( - 'GitHub webhook update failure response: %s', - debug_data, + 'GitHub webhook update failure response.', + debug_data=debug_data, ) integration.remove_secret() @@ -486,36 +484,35 @@ def send_build_status(self, build, commit, state, link_to_build=False): ) if resp.status_code == 201: log.info( - "GitHub commit status created for project: %s, commit status: %s", - project.slug, - github_build_state, + "GitHub commit status created for project.", + project_slug=project.slug, + commit_status=github_build_state, ) return True if resp.status_code in [401, 403, 404]: log.info( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s, user=%s, status=%s, url=%s', - project.slug, - self.user.username, - resp.status_code, - statuses_url, + 'GitHub project does not exist or user does not have permissions.', + project_slug=project.slug, + user_username=self.user.username, + http_status_code=resp.status_code, + statuses_url=statuses_url, ) return False log.warning( - 'Unknown GitHub status API response: project=%s, user=%s, status_code=%s', - project.slug, - self.user, - resp.status_code + 'Unknown GitHub status API response.', + project_slug=project.slug, + user_username=self.user.username, + htttp_status_code=resp.status_code, ) return False # Catch exceptions with request or deserializing JSON except (RequestException, ValueError): log.exception( - 'GitHub commit status creation failed for project: %s', - project.slug, + 'GitHub commit status creation failed for project.', + project_slug=project.slug, ) # Response data should always be JSON, still try to log if not # though @@ -528,8 +525,8 @@ def send_build_status(self, build, commit, state, link_to_build=False): debug_data = resp log.debug( - 'GitHub commit status creation failure response: %s', - debug_data, + 'GitHub commit status creation failure response.', + debug_data=debug_data, ) return False diff --git a/readthedocs/oauth/services/gitlab.py b/readthedocs/oauth/services/gitlab.py index f86d222f1b7..123e5bab555 100644 --- a/readthedocs/oauth/services/gitlab.py +++ b/readthedocs/oauth/services/gitlab.py @@ -1,7 +1,7 @@ """OAuth utility functions.""" import json -import logging +import structlog import re from urllib.parse import quote_plus, urlparse @@ -21,7 +21,7 @@ from ..models import RemoteOrganization, RemoteRepository from .base import Service, SyncServiceError -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class GitLabService(Service): @@ -147,15 +147,14 @@ def sync_organizations(self): remote_repositories.append(remote_repository) else: log.warning( - 'GitLab project does not exist or user does not have ' - 'permissions: project=%s', - repo['name_with_namespace'], + 'GitLab project does not exist or user does not have permissions.', + repository=repo['name_with_namespace'], ) except Exception: log.exception( - 'Error creating GitLab repository=%s', - repo['name_with_namespace'], + 'Error creating GitLab repository', + repository=repo['name_with_namespace'], ) except (TypeError, ValueError): @@ -200,8 +199,8 @@ def create_repository(self, fields, privacy=None, organization=None): if repo.organization and repo.organization != organization: log.debug( - 'Not importing %s because mismatched orgs', - fields['name'], + 'Not importing because mismatched orgs', + repository=fields['name'], ) return None @@ -249,9 +248,9 @@ def create_repository(self, fields, privacy=None, organization=None): return repo log.info( - 'Not importing %s because mismatched type: visibility=%s', - fields['path_with_namespace'], - fields['visibility'], + 'Not importing repository because mismatched type.', + repository=fields['path_with_namespace'], + visibility=fields['visibility'], ) def create_organization(self, fields): @@ -365,21 +364,20 @@ def get_provider_data(self, project, integration): integration.save() log.info( - 'GitLab integration updated with provider data for project: %s', - project, + 'GitLab integration updated with provider data for project.', + project_slug=project.slug, ) break else: log.info( - 'GitLab project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'GitLab project does not exist or user does not have permissions.', + project_slug=project.slug, ) except Exception: log.exception( - 'GitLab webhook Listing failed for project: %s', - project, + 'GitLab webhook Listing failed for project.', + project_slug=project.slug, ) return integration.provider_data @@ -429,27 +427,26 @@ def setup_webhook(self, project, integration=None): integration.provider_data = resp.json() integration.save() log.info( - 'GitLab webhook creation successful for project: %s', - project, + 'GitLab webhook creation successful for project.', + project_slug=project.slug, ) return (True, resp) if resp.status_code in [401, 403, 404]: log.info( - 'Gitlab project does not exist or user does not have ' - 'permissions: project=%s', - project, + 'Gitlab project does not exist or user does not have permissions.', + project_slug=project.slug, ) except (RequestException, ValueError): log.exception( - 'GitLab webhook creation failed for project: %s', - project, + 'GitLab webhook creation failed for project.', + project_slug=project.slug, ) else: log.error( - 'GitLab webhook creation failed for project: %s', - project, + 'GitLab webhook creation failed for project.', + project_slug=project.slug, ) # Always remove secret and return False if we don't return True above @@ -507,8 +504,8 @@ def update_webhook(self, project, integration): integration.provider_data = recv_data integration.save() log.info( - 'GitLab webhook update successful for project: %s', - project, + 'GitLab webhook update successful for project.', + project_slug=project.slug, ) return (True, resp) @@ -520,19 +517,19 @@ def update_webhook(self, project, integration): # Catch exceptions with request or deserializing JSON except (AttributeError, RequestException, ValueError): log.exception( - 'GitLab webhook update failed for project: %s', - project, + 'GitLab webhook update failed for project.', + project_slug=project.slug, ) else: log.error( - 'GitLab webhook update failed for project: %s', - project, + 'GitLab webhook update failed for project.', + project_slug=project.slug, ) try: debug_data = resp.json() except ValueError: debug_data = resp.content - log.debug('GitLab webhook update failure response: %s', debug_data) + log.debug('GitLab webhook update failure response.', debug_data=debug_data) integration.remove_secret() return (False, resp) @@ -589,17 +586,19 @@ def send_build_status(self, build, commit, state, link_to_build=False): if resp.status_code == 201: log.info( - "GitLab commit status created for project: %s, commit status: %s", - project.slug, - gitlab_build_state, + "GitLab commit status created for project.", + project_slug=project.slug, + commit_status=gitlab_build_state, ) return True if resp.status_code in [401, 403, 404]: log.info( - 'GitLab project does not exist or user does not have permissions: ' - 'project=%s, user=%s, status=%s, url=%s', - project.slug, self.user.username, resp.status_code, statuses_url, + 'GitLab project does not exist or user does not have permissions.', + project_slug=project.slug, + user_username=self.user.username, + http_status_code=resp.status_code, + statuses_url=statuses_url, ) return False @@ -608,8 +607,8 @@ def send_build_status(self, build, commit, state, link_to_build=False): # Catch exceptions with request or deserializing JSON except (RequestException, ValueError): log.exception( - 'GitLab commit status creation failed for project: %s', - project.slug, + 'GitLab commit status creation failed for project.', + project_slug=project.slug, ) # Response data should always be JSON, still try to log if not # though @@ -622,7 +621,7 @@ def send_build_status(self, build, commit, state, link_to_build=False): debug_data = resp log.debug( - 'GitLab commit status creation failure response: %s', - debug_data, + 'GitLab commit status creation failure response.', + debug_data=debug_data, ) return False diff --git a/readthedocs/oauth/tasks.py b/readthedocs/oauth/tasks.py index 56df09564be..59c2784800d 100644 --- a/readthedocs/oauth/tasks.py +++ b/readthedocs/oauth/tasks.py @@ -1,6 +1,6 @@ """Tasks for OAuth services.""" -import logging +import structlog from allauth.socialaccount.providers import registry as allauth_registry from django.contrib.auth.models import User @@ -22,7 +22,7 @@ from .services import registry -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) @PublicTask.permission_check(user_id_matches) @@ -33,7 +33,7 @@ def sync_remote_repositories(user_id): return # TODO: remove this log once we find out what's causing OOM - log.info('Running readthedocs.oauth.tasks.sync_remote_repositories. locals=%s', locals()) + log.info('Running readthedocs.oauth.tasks.sync_remote_repositories.', locals=locals()) failed_services = set() for service_cls in registry: @@ -67,9 +67,9 @@ def sync_remote_repositories_organizations(organization_slugs=None): if organization_slugs: query = Organization.objects.filter(slug__in=organization_slugs) log.info( - 'Triggering SSO re-sync for organizations. slugs=%s count=%s', - organization_slugs, - query.count(), + 'Triggering SSO re-sync for organizations.', + organization_slugs=organization_slugs, + count=query.count(), ) else: query = ( @@ -78,17 +78,17 @@ def sync_remote_repositories_organizations(organization_slugs=None): .values_list('organization', flat=True) ) log.info( - 'Triggering SSO re-sync for all organizations. count=%s', - query.count(), + 'Triggering SSO re-sync for all organizations.', + count=query.count(), ) n_task = -1 for organization in query: members = AdminPermission.members(organization) log.info( - 'Triggering SSO re-sync for organization. organization=%s users=%s', - organization.slug, - members.count(), + 'Triggering SSO re-sync for organization.', + organization_slug=organization.slug, + count=members.count(), ) for user in members: n_task += 1 diff --git a/readthedocs/oauth/utils.py b/readthedocs/oauth/utils.py index 730a5c450d8..44b7bf8c924 100644 --- a/readthedocs/oauth/utils.py +++ b/readthedocs/oauth/utils.py @@ -1,6 +1,6 @@ """Support code for OAuth, including webhook support.""" -import logging +import structlog from django.contrib import messages from django.utils.translation import ugettext_lazy as _ @@ -14,7 +14,7 @@ from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) SERVICE_MAP = { Integration.GITHUB_WEBHOOK: GitHubService, diff --git a/readthedocs/organizations/signals.py b/readthedocs/organizations/signals.py index 0896e14e3e6..89677d948eb 100644 --- a/readthedocs/organizations/signals.py +++ b/readthedocs/organizations/signals.py @@ -1,6 +1,6 @@ """Organization signals.""" -import logging +import structlog from allauth.account.signals import user_signed_up from django.db.models import Count @@ -20,7 +20,7 @@ from .tasks import mark_organization_assets_not_cleaned as mark_organization_assets_not_cleaned_task -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) # pylint: disable=unused-argument @@ -50,7 +50,7 @@ def remove_organization_completely(sender, instance, using, **kwargs): - Artifacts (HTML, PDF, etc) """ organization = instance - log.info('Removing Organization %s completely', organization.slug) + log.info('Removing organization completely', organization_slug=organization.slug) # ``Project`` has a ManyToMany relationship with ``Organization``. We need # to be sure that the projects we are deleting here belongs only to the diff --git a/readthedocs/organizations/tasks.py b/readthedocs/organizations/tasks.py index 68e7fc62c0c..ed89cf9bce7 100644 --- a/readthedocs/organizations/tasks.py +++ b/readthedocs/organizations/tasks.py @@ -1,12 +1,12 @@ """Organization's tasks related.""" -import logging +import structlog from readthedocs.builds.models import Build from readthedocs.worker import app -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) @app.task(queue='web') @@ -15,11 +15,11 @@ def mark_organization_assets_not_cleaned(build_pk): try: build = Build.objects.get(pk=build_pk) except Build.DoesNotExist: - log.info("Build does not exist. build=%s", build_pk) + log.info("Build does not exist.", build_pk=build_pk) return organization = build.project.organizations.first() if organization and organization.artifacts_cleaned: - log.info("Marking organization as not cleaned. organization=%s", organization.slug) + log.info("Marking organization as not cleaned.", origanization_slug=organization.slug) organization.artifacts_cleaned = False organization.save() diff --git a/readthedocs/organizations/utils.py b/readthedocs/organizations/utils.py index 55d1b4b021a..a708846e08c 100644 --- a/readthedocs/organizations/utils.py +++ b/readthedocs/organizations/utils.py @@ -1,17 +1,17 @@ """Utilities for organizations.""" -import logging +import structlog from readthedocs.core.utils import send_email # pylint: disable=invalid-name -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def send_team_invite_email(invite, request): """Send an organization team invite email.""" - log.info('Sending team invite for %s to %s', invite.team, invite.email) + log.info('Sending team invite.', team=invite.team, email=invite.email) send_email( invite.email, subject='Join your team at Read the Docs', @@ -30,9 +30,9 @@ def send_team_invite_email(invite, request): def send_team_add_email(team_member, request): """Send an organization team add email.""" log.info( - 'Sending team add notification for %s to %s', - team_member.team, - team_member.member.email, + 'Sending team add notification.', + team=team_member.team, + email=team_member.member.email, ) send_email( team_member.member.email, diff --git a/readthedocs/organizations/views/public.py b/readthedocs/organizations/views/public.py index fd427a7f0a5..5458b481547 100644 --- a/readthedocs/organizations/views/public.py +++ b/readthedocs/organizations/views/public.py @@ -1,6 +1,6 @@ """Views that don't require login.""" # pylint: disable=too-many-ancestors -import logging +import structlog from django.db.models import F from django.http import HttpResponseRedirect @@ -19,7 +19,7 @@ ) from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class OrganizationTemplateView(CheckOrganizationsEnabled, TemplateView): diff --git a/readthedocs/payments/utils.py b/readthedocs/payments/utils.py index ab0ab100e24..865a4f01f0d 100644 --- a/readthedocs/payments/utils.py +++ b/readthedocs/payments/utils.py @@ -7,7 +7,7 @@ :py:class:`readthedocs.payments.forms.StripeResourceMixin`. """ -import logging +import structlog import stripe @@ -15,7 +15,7 @@ stripe.api_key = settings.STRIPE_SECRET -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def delete_customer(customer_id): @@ -25,8 +25,8 @@ def delete_customer(customer_id): return customer.delete() except stripe.error.InvalidRequestError: log.exception( - 'Customer not deleted. Customer not found on Stripe. customer=%s', - customer_id, + 'Customer not deleted. Customer not found on Stripe.', + stripe_customer=customer_id, ) @@ -39,8 +39,7 @@ def cancel_subscription(customer_id, subscription_id): return subscription.delete() except stripe.error.StripeError: log.exception( - 'Subscription not cancelled. Customer/Subscription not found on Stripe. ' - 'customer=%s subscription=%s', - customer_id, - subscription_id, + 'Subscription not cancelled. Customer/Subscription not found on Stripe. ', + stripe_customer=customer_id, + stripe_subscription=subscription_id, ) diff --git a/readthedocs/projects/constants.py b/readthedocs/projects/constants.py index e43dc134b82..ade362a6f62 100644 --- a/readthedocs/projects/constants.py +++ b/readthedocs/projects/constants.py @@ -303,8 +303,6 @@ ('other', 'Other'), ) -LOG_TEMPLATE = '(Build) [%(project)s:%(version)s] %(msg)s' - PROJECT_PK_REGEX = r'(?:[-\w]+)' PROJECT_SLUG_REGEX = r'(?:[-\w]+)' diff --git a/readthedocs/projects/filters.py b/readthedocs/projects/filters.py index a0fb3b990be..45dd99d698d 100644 --- a/readthedocs/projects/filters.py +++ b/readthedocs/projects/filters.py @@ -1,11 +1,11 @@ -import logging +import structlog from django.db.models import Count, F, Max from django.forms.widgets import HiddenInput from django.utils.translation import ugettext_lazy as _ from django_filters import CharFilter, ChoiceFilter, FilterSet, OrderingFilter -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class VersionSortOrderingFilter(OrderingFilter): diff --git a/readthedocs/projects/models.py b/readthedocs/projects/models.py index 5ee7744c2da..f694a435984 100644 --- a/readthedocs/projects/models.py +++ b/readthedocs/projects/models.py @@ -2,7 +2,7 @@ import fnmatch import hashlib import hmac -import logging +import structlog import os import re from shlex import quote @@ -62,7 +62,7 @@ MEDIA_TYPES, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def default_privacy_level(): @@ -657,8 +657,9 @@ def regex_urlconf(self): if '\\$' in to_convert: log.warning( - 'Unconverted variable in a project URLConf: project=%s to_convert=%s', - self, to_convert + 'Unconverted variable in a project URLConf.', + project_slug=self.slug, + to_convert=to_convert, ) return to_convert diff --git a/readthedocs/projects/tasks.py b/readthedocs/projects/tasks.py index ff24ede494a..eff027d8f4c 100644 --- a/readthedocs/projects/tasks.py +++ b/readthedocs/projects/tasks.py @@ -7,7 +7,6 @@ import datetime import json -import logging import os import shutil import signal @@ -25,6 +24,8 @@ from slumber.exceptions import HttpClientError from sphinx.ext import intersphinx +import structlog + from readthedocs.api.v2.client import api as api_v2 from readthedocs.builds import tasks as build_tasks from readthedocs.builds.constants import ( @@ -70,11 +71,10 @@ from readthedocs.vcs_support import utils as vcs_support_utils from readthedocs.worker import app -from .constants import LOG_TEMPLATE from .exceptions import RepositoryError from .models import HTMLFile, ImportedFile, Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class CachedEnvironmentMixin: @@ -89,22 +89,16 @@ def pull_cached_environment(self): msg = 'Checking for cached environment' log.debug( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + msg, + project_slug=self.project.slug, + version_slug=self.version.slug, ) if build_environment_storage.exists(filename): msg = 'Pulling down cached environment from storage' log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + msg, + project_slug=self.project.slug, + version_slug=self.version.slug, ) remote_fd = build_environment_storage.open(filename, mode='rb') with tarfile.open(fileobj=remote_fd) as tar: @@ -142,12 +136,9 @@ def push_cached_environment(self): with open(tmp_filename, 'rb') as fd: msg = 'Pushing up cached environment to storage' log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + msg, + project_slug=self.project.slug, + version_slug=self.version.slug, ) build_environment_storage.save( self.version.get_storage_environment_cache_path(), @@ -204,17 +195,11 @@ def sync_repo(self, environment): ) # Get the actual code on disk - msg = 'Checking out version {slug}: {identifier}'.format( - slug=self.version.slug, - identifier=self.version.identifier, - ) log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + 'Checking out version.', + project_slug=self.project.slug, + version_slug=self.version.slug, + version_identifier=self.version.identifier, ) version_repo = self.get_vcs_repo(environment) version_repo.update() @@ -241,7 +226,7 @@ def sync_versions(self, version_repo): # have already cloned the repository locally. The latter happens # when triggering a normal build. branches, tags = version_repo.lsremote - log.info('Remote versions: branches=%s tags=%s', branches, tags) + log.info('Remote versions.', branches=branches, tags=tags) branches_data = [] tags_data = [] @@ -377,9 +362,9 @@ def run(self, version_pk): # pylint: disable=arguments-differ environment=self.get_vcs_env_vars(), ) log.info( - 'Running sync_repository_task: project=%s version=%s', - self.project.slug, - self.version.slug, + 'Running sync_repository_task.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) with environment: @@ -398,9 +383,9 @@ def run(self, version_pk): # pylint: disable=arguments-differ log.warning('There was an error with the repository', exc_info=True) except vcs_support_utils.LockTimeout: log.info( - 'Lock still active: project=%s version=%s', - self.project.slug, - self.version.slug, + 'Lock still active.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) except Exception: # Catch unhandled errors when syncing @@ -430,10 +415,10 @@ def update_versions_from_repository(self, environment): not version_repo.supports_lsremote, not self.project.has_feature(Feature.VCS_REMOTE_LISTING), ]): - log.info('Syncing repository via full clone. project=%s', self.project.slug) + log.info('Syncing repository via full clone.', project_slug=self.project.slug) self.sync_repo(environment) else: - log.info('Syncing repository via remote listing. project=%s', self.project.slug) + log.info('Syncing repository via remote listing.', project_slug=self.project.slug) self.sync_versions(version_repo) @@ -548,11 +533,11 @@ def run( if self.build.get('status') == DuplicatedBuildError.status: log.warning( - 'NOOP: build is marked as duplicated. project=%s version=%s build=%s commit=%s', - self.project.slug, - self.version.slug, - build_pk, - self.commit, + 'NOOP: build is marked as duplicated.', + project_slug=self.project.slug, + version_slug=self.version.slug, + build_id=build_pk, + commit=self.commit, ) return True @@ -566,19 +551,18 @@ def run( ) except Exception: log.exception( - 'Error while hitting/parsing API for concurrent limit checks from builder. ' - 'project=%s version=%s', - self.project.slug, - self.version.slug, + 'Error while hitting/parsing API for concurrent limit checks from builder.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) concurrency_limit_reached = False max_concurrent_builds = settings.RTD_MAX_CONCURRENT_BUILDS if concurrency_limit_reached: log.warning( - 'Delaying tasks due to concurrency limit. project=%s version=%s', - self.project.slug, - self.version.slug, + 'Delaying tasks due to concurrency limit.', + project_slug=self.project.slug, + version_slug=self.version.slug, ) # This is done automatically on the environment context, but @@ -699,16 +683,11 @@ def run_setup(self, record=True): self.additional_vcs_operations(environment) if environment.failure or self.config is None: - msg = 'Failing build because of setup failure: {}'.format( - environment.failure, - ) log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + 'Failing build because of setup failure.', + failure=environment.failure, + project_slug=self.project.slug, + version_slug=self.version.slug, ) # Send notification to users only if the build didn't fail because @@ -772,12 +751,9 @@ def run_build(self, record): self.config.python_interpreter in ('conda', 'mamba'), ]): log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': 'Using conda', - } + 'Using conda', + project_slug=self.project.slug, + version_slug=self.version.slug, ) python_env_cls = Conda self.python_env = python_env_cls( @@ -869,12 +845,9 @@ def run_build(self, record): status=BUILD_STATUS_FAILURE ) log.warning( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': msg, - } + msg, + project_slug=self.project.slug, + version_slug=self.version.slug, ) build_complete.send(sender=Build, build=self.build_env.build) @@ -933,12 +906,9 @@ def setup_vcs(self, environment): ) log.info( - LOG_TEMPLATE, - { - 'project': self.project.slug, - 'version': self.version.slug, - 'msg': 'Updating docs from VCS', - } + 'Updating docs from VCS', + project_slug=self.project.slug, + version_slug=self.version.slug, ) try: self.sync_repo(environment) @@ -1044,12 +1014,9 @@ def store_build_artifacts( :param epub: whether to save ePub output """ log.info( - LOG_TEMPLATE, - { - 'project': self.version.project.slug, - 'version': self.version.slug, - 'msg': 'Writing build artifacts to media storage', - }, + 'Writing build artifacts to media storage', + project_slug=self.project.slug, + version_slug=self.version.slug, ) types_to_copy = [] @@ -1090,12 +1057,11 @@ def store_build_artifacts( version_type=self.version.type, ) log.info( - LOG_TEMPLATE, - { - 'project': self.version.project.slug, - 'version': self.version.slug, - 'msg': f'Writing {media_type} to media storage - {to_path}', - }, + 'Writing to media storage.', + media_type=media_type, + to_path=to_path, + project_slug=self.version.project.slug, + version_slug=self.version.slug, ) try: build_media_storage.sync_directory(from_path, to_path) @@ -1103,12 +1069,11 @@ def store_build_artifacts( # Ideally this should just be an IOError # but some storage backends unfortunately throw other errors log.exception( - LOG_TEMPLATE, - { - 'project': self.version.project.slug, - 'version': self.version.slug, - 'msg': f'Error copying {from_path} to storage (not failing build)', - }, + 'Error copying to storage (not failing build)', + from_path=from_path, + to_path=to_path, + project_slug=self.version.project.slug, + version_slug=self.version.slug, ) for media_type in types_to_delete: @@ -1119,12 +1084,11 @@ def store_build_artifacts( version_type=self.version.type, ) log.info( - LOG_TEMPLATE, - { - 'project': self.version.project.slug, - 'version': self.version.slug, - 'msg': f'Deleting {media_type} from media storage - {media_path}', - }, + 'Deleting from media storage', + media_type=media_type, + media_path=media_path, + project_slug=self.version.project.slug, + version_slug=self.version.slug, ) try: build_media_storage.delete_directory(media_path) @@ -1132,12 +1096,10 @@ def store_build_artifacts( # Ideally this should just be an IOError # but some storage backends unfortunately throw other errors log.exception( - LOG_TEMPLATE, - { - 'project': self.version.project.slug, - 'version': self.version.slug, - 'msg': f'Error deleting {media_path} from storage (not failing build)', - }, + 'Error deleting from storage (not failing build)', + media_path=media_path, + project_slug=self.version.project.slug, + version_slug=self.version.slug, ) def update_app_instances( @@ -1163,8 +1125,8 @@ def update_app_instances( }) except HttpClientError: log.exception( - 'Updating version failed, skipping file sync: version=%s', - self.version, + 'Updating version failed, skipping file sync.', + version_slug=self.version.slug, ) # Index search data @@ -1365,28 +1327,20 @@ def fileify(version_pk, commit, build, search_ranking, search_ignore): project = version.project # TODO: remove this log once we find out what's causing OOM - log.info('Running readthedocs.projects.tasks.fileify. locals=%s', locals()) + log.info('Running readthedocs.projects.tasks.fileify.', locals=locals()) if not commit: log.warning( - LOG_TEMPLATE, - { - 'project': project.slug, - 'version': version.slug, - 'msg': ( - 'Search index not being built because no commit information' - ), - }, + 'Search index not being built because no commit information', + project_slug=project.slug, + version_slug=version.slug, ) return log.info( - LOG_TEMPLATE, - { - 'project': version.project.slug, - 'version': version.slug, - 'msg': 'Creating ImportedFiles', - }, + 'Creating ImportedFiles', + project_slug=version.project.slug, + version_slug=version.slug, ) try: _create_imported_files( @@ -1456,7 +1410,7 @@ class MockApp: config = MockConfig() def warn(self, msg): - log.warning('Sphinx MockApp: %s', msg) + log.warning('Sphinx MockApp.', msg=msg) # Re-create all objects from the new build of the version object_file_url = build_media_storage.url(object_file) @@ -1484,10 +1438,10 @@ def warn(self, msg): display_name = einfo[3] except Exception: log.exception( - 'Error while getting sphinx domain information for %s:%s:%s. Skipping.', - version.project.slug, - version.slug, - f'{domain}->{name}', + 'Error while getting sphinx domain information. Skipping...', + project_slug=version.project.slug, + version_slug=version.slug, + sphinx_domain='{domain}->{name}', ) continue @@ -1508,11 +1462,11 @@ def warn(self, msg): if not html_file: log.debug( - '[%s] [%s] [Build: %s] HTMLFile object not found. File: %s', - version.project, - version, - build, - doc_name + 'HTMLFile object not found.', + project_slug=version.project.slug, + version_slug=version.slug, + build_id=build, + doc_name=doc_name ) # Don't create Sphinx Domain objects @@ -1548,8 +1502,8 @@ def clean_build(version_pk): not version.project.has_feature(Feature.CLEAN_AFTER_BUILD) ): log.info( - 'Skipping build files deletetion for version: %s', - version_pk, + 'Skipping build files deletetion for version.', + version_id=version_pk, ) return False # NOTE: we are skipping the deletion of the `artifacts` dir @@ -1563,10 +1517,10 @@ def clean_build(version_pk): ) try: with version.project.repo_nonblockinglock(version): - log.info('Removing: %s', del_dirs) + log.info('Removing directories.', directories=del_dirs) remove_dirs(del_dirs) except vcs_support_utils.LockTimeout: - log.info('Another task is running. Not removing: %s', del_dirs) + log.info('Another task is running. Not removing...', directories=del_dirs) else: return True @@ -1681,7 +1635,7 @@ def remove_dirs(paths): :param paths: list containing PATHs where file is on disk """ for path in paths: - log.info('Removing %s', path) + log.info('Removing directory.', path=path) shutil.rmtree(path, ignore_errors=True) @@ -1693,7 +1647,7 @@ def remove_build_storage_paths(paths): :param paths: list of paths in build media storage to delete """ for storage_path in paths: - log.info('Removing %s from media storage', storage_path) + log.info('Removing path from media storage.', path=storage_path) build_media_storage.delete_directory(storage_path) @@ -1785,8 +1739,8 @@ def finish_inactive_builds(): builds_finished += 1 log.info( - 'Builds marked as "Terminated due inactivity": %s', - builds_finished, + 'Builds marked as "Terminated due inactivity".', + count=builds_finished, ) diff --git a/readthedocs/projects/utils.py b/readthedocs/projects/utils.py index 83c3c5eb383..6480d9874f7 100644 --- a/readthedocs/projects/utils.py +++ b/readthedocs/projects/utils.py @@ -1,13 +1,13 @@ """Utility functions used by projects.""" import csv -import logging +import structlog import os from django.conf import settings from django.http import StreamingHttpResponse -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) # TODO make this a classmethod of Version diff --git a/readthedocs/projects/views/base.py b/readthedocs/projects/views/base.py index b0d4600eda3..2a7a4de5bb4 100644 --- a/readthedocs/projects/views/base.py +++ b/readthedocs/projects/views/base.py @@ -1,5 +1,5 @@ """Mix-in classes for project views.""" -import logging +import structlog from datetime import timedelta from functools import lru_cache @@ -12,7 +12,7 @@ from readthedocs.projects.exceptions import ProjectSpamError from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class ProjectOnboardMixin: @@ -89,11 +89,9 @@ class ProjectSpamMixin: """Protects POST views from spammers.""" def post(self, request, *args, **kwargs): + log.bind(user_username=request.user.username) if request.user.profile.banned: - log.info( - 'Rejecting project POST from shadowbanned user %s', - request.user, - ) + log.info('Rejecting project POST from shadowbanned user.') return HttpResponseRedirect(self.get_failure_url()) try: return super().post(request, *args, **kwargs) @@ -104,12 +102,9 @@ def post(self, request, *args, **kwargs): if request.user.date_joined > date_maturity: request.user.profile.banned = True request.user.profile.save() - log.info( - 'Spam detected from new user, shadowbanned user %s', - request.user, - ) + log.info('Spam detected from new user, shadowbanned user.') else: - log.info('Spam detected from user %s', request.user) + log.info('Spam detected from user.') return HttpResponseRedirect(self.get_failure_url()) def get_failure_url(self): diff --git a/readthedocs/projects/views/private.py b/readthedocs/projects/views/private.py index f87c80196b4..9a57d26bb57 100644 --- a/readthedocs/projects/views/private.py +++ b/readthedocs/projects/views/private.py @@ -1,6 +1,6 @@ """Project views for authenticated users.""" -import logging +import structlog from allauth.socialaccount.models import SocialAccount from django.conf import settings @@ -80,7 +80,7 @@ ) from readthedocs.search.models import SearchQuery -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class ProjectDashboard(PrivateViewMixin, ListView): @@ -212,7 +212,7 @@ def form_valid(self, form): version = form.save() if form.has_changed(): if 'active' in form.changed_data and version.active is False: - log.info('Removing files for version %s', version.slug) + log.info('Removing files for version.', version_slug=version.slug) tasks.clean_project_resources( version.project, version, @@ -241,7 +241,7 @@ def post(self, request, *args, **kwargs): if not version.active: version.built = False version.save() - log.info('Removing files for version %s', version.slug) + log.info('Removing files for version.', version_slug=version.slug) tasks.clean_project_resources( version.project, version, diff --git a/readthedocs/projects/views/public.py b/readthedocs/projects/views/public.py index 0f315ea8e77..a4e895570e5 100644 --- a/readthedocs/projects/views/public.py +++ b/readthedocs/projects/views/public.py @@ -2,7 +2,7 @@ import hashlib import json -import logging +import structlog import mimetypes import operator import os @@ -42,8 +42,8 @@ from ..constants import PRIVATE from .base import ProjectOnboardMixin -log = logging.getLogger(__name__) -search_log = logging.getLogger(__name__ + '.search') +log = structlog.get_logger(__name__) +search_log = structlog.get_logger(__name__ + '.search') mimetypes.add_type('application/epub+zip', '.epub') diff --git a/readthedocs/proxito/middleware.py b/readthedocs/proxito/middleware.py index 943ce8a7891..397a731c56e 100644 --- a/readthedocs/proxito/middleware.py +++ b/readthedocs/proxito/middleware.py @@ -5,11 +5,12 @@ Additional processing is done to get the project from the URL in the ``views.py`` as well. """ -import logging import re import sys from urllib.parse import urlparse +import structlog + from django.conf import settings from django.shortcuts import redirect, render from django.urls import reverse @@ -18,7 +19,7 @@ from readthedocs.projects.models import Domain, Project, ProjectRelationship from readthedocs.proxito import constants -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa def map_host_to_project_slug(request): # pylint: disable=too-many-return-statements @@ -52,7 +53,7 @@ def map_host_to_project_slug(request): # pylint: disable=too-many-return-statem project_slug = request.META['HTTP_X_RTD_SLUG'].lower() if Project.objects.filter(slug=project_slug).exists(): request.rtdheader = True - log.info('Setting project based on X_RTD_SLUG header: %s', project_slug) + log.info('Setting project based on X_RTD_SLUG header.', project_slug=project_slug) return project_slug if public_domain in host or host == 'proxito': @@ -60,24 +61,24 @@ def map_host_to_project_slug(request): # pylint: disable=too-many-return-statem if public_domain_parts == host_parts[1:]: project_slug = host_parts[0] request.subdomain = True - log.debug('Proxito Public Domain: host=%s', host) + log.debug('Proxito Public Domain.', host=host) if Domain.objects.filter(project__slug=project_slug).filter( canonical=True, https=True, ).exists(): - log.debug('Proxito Public Domain -> Canonical Domain Redirect: host=%s', host) + log.debug('Proxito Public Domain -> Canonical Domain Redirect.', host=host) request.canonicalize = constants.REDIRECT_CANONICAL_CNAME elif ( ProjectRelationship.objects. filter(child__slug=project_slug).exists() ): - log.debug('Proxito Public Domain -> Subproject Main Domain Redirect: host=%s', host) + log.debug('Proxito Public Domain -> Subproject Main Domain Redirect.', host=host) request.canonicalize = constants.REDIRECT_SUBPROJECT_MAIN_DOMAIN return project_slug # TODO: This can catch some possibly valid domains (docs.readthedocs.io.com) for example # But these feel like they might be phishing, etc. so let's block them for now. - log.warning('Weird variation on our hostname: host=%s', host) + log.warning('Weird variation on our hostname.', host=host) return render( request, 'core/dns-404.html', context={'host': host}, status=400 ) @@ -89,10 +90,10 @@ def map_host_to_project_slug(request): # pylint: disable=too-many-return-statem project_slug, version_slug = host_parts[0].split('--', 1) request.external_domain = True request.host_version_slug = version_slug - log.debug('Proxito External Version Domain: host=%s', host) + log.debug('Proxito External Version Domain.', host=host) return project_slug except ValueError: - log.warning('Weird variation on our hostname: host=%s', host) + log.warning('Weird variation on our hostname.', host=host) return render( request, 'core/dns-404.html', context={'host': host}, status=400 ) @@ -103,11 +104,11 @@ def map_host_to_project_slug(request): # pylint: disable=too-many-return-statem project_slug = domain.project.slug request.cname = True request.domain = domain - log.debug('Proxito CNAME: host=%s', host) + log.debug('Proxito CNAME.', host=host) if domain.https and not request.is_secure(): # Redirect HTTP -> HTTPS (302) for this custom domain - log.debug('Proxito CNAME HTTPS Redirect: host=%s', host) + log.debug('Proxito CNAME HTTPS Redirect.', host=host) request.canonicalize = constants.REDIRECT_HTTPS # NOTE: consider redirecting non-canonical custom domains to the canonical one @@ -116,7 +117,7 @@ def map_host_to_project_slug(request): # pylint: disable=too-many-return-statem return project_slug # Some person is CNAMEing to us without configuring a domain - 404. - log.debug('CNAME 404: host=%s', host) + log.debug('CNAME 404.', host=host) return render( request, 'core/dns-404.html', context={'host': host}, status=404 ) @@ -191,14 +192,14 @@ def add_user_headers(self, request, response): for http_header in request.domain.http_headers.all(): if http_header.name.lower() in response_headers: log.error( - 'Overriding an existing response HTTP header. header=%s domain=%s', - http_header.name, - request.domain.domain, + 'Overriding an existing response HTTP header.', + http_header=http_header.name, + domain=request.domain.domain, ) log.info( - 'Adding custom response HTTP header. header=%s domain=%s', - http_header.name, - request.domain.domain, + 'Adding custom response HTTP header.', + http_header=http_header.name, + domain=request.domain.domain, ) if http_header.only_if_secure_request and not request.is_secure(): @@ -294,10 +295,17 @@ def process_request(self, request): # noqa # We make sure there is _always_ a single slash in front to ensure relative redirects, # instead of `//` redirects which are actually alternative domains. final_url = '/' + final_url.lstrip('/') - log.info('Proxito Slash Redirect: from=%s to=%s', request.get_full_path(), final_url) + log.info( + 'Proxito Slash Redirect.', + from_url=request.get_full_path(), + to_url=final_url, + ) return redirect(final_url) - log.debug('Proxito Project: slug=%s', ret) + log.debug( + 'Proxito Project.', + project_slug=ret, + ) # Otherwise set the slug on the request request.host_project_slug = request.slug = ret @@ -318,8 +326,10 @@ def process_request(self, request): # noqa url_key = f'readthedocs.urls.fake.{project.slug}.{project_timestamp}' log.info( - 'Setting URLConf: project=%s url_key=%s urlconf=%s', - project, url_key, project.urlconf, + 'Setting URLConf', + project_slug=project.slug, + url_key=url_key, + urlconf=project.urlconf, ) if url_key not in sys.modules: sys.modules[url_key] = project.proxito_urlconf diff --git a/readthedocs/proxito/views/decorators.py b/readthedocs/proxito/views/decorators.py index a97a78e9be8..11a744e72b6 100644 --- a/readthedocs/proxito/views/decorators.py +++ b/readthedocs/proxito/views/decorators.py @@ -1,11 +1,11 @@ -import logging +import structlog from functools import wraps from django.http import Http404 from readthedocs.projects.models import Project, ProjectRelationship -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa def map_subproject_slug(view_func): @@ -40,8 +40,9 @@ def inner_view( # noqa subproject = rel.child else: log.warning( - 'The slug is not subproject of project. subproject_slug=%s project_slug=%s', - subproject_slug, kwargs['project'].slug + 'The slug is not subproject of project.', + subproject_slug=subproject_slug, + project_slug=kwargs['project'].slug, ) raise Http404('Invalid subproject slug') return view_func(request, subproject=subproject, *args, **kwargs) @@ -67,8 +68,8 @@ def inner_view( # noqa if not project_slug: project_slug = getattr(request, 'host_project_slug', None) log.debug( - 'Inserting project slug from request slug=[%s]', - project_slug + 'Inserting project slug from request.', + project_slug=project_slug, ) try: project = Project.objects.get(slug=project_slug) diff --git a/readthedocs/proxito/views/mixins.py b/readthedocs/proxito/views/mixins.py index 88c4742e530..48ea05c5aa7 100644 --- a/readthedocs/proxito/views/mixins.py +++ b/readthedocs/proxito/views/mixins.py @@ -1,5 +1,5 @@ import copy -import logging +import structlog import mimetypes from urllib.parse import urlparse, urlunparse @@ -24,7 +24,7 @@ from readthedocs.redirects.exceptions import InfiniteRedirectException from readthedocs.storage import build_media_storage -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa class ServeDocsMixin: @@ -105,7 +105,7 @@ def _serve_docs_python(self, request, final_project, path): .. warning:: Don't do this in production! """ - log.debug('[Django serve] path=%s, project=%s', path, final_project.slug) + log.debug('Django serve.', path=path, project_slug=final_project.slug) root_path = build_media_storage.path('') # Serve from Python @@ -125,8 +125,11 @@ def _serve_docs_nginx(self, request, final_project, version_slug, path, download path = path[1:] path = f'/proxito/{path}' - log.debug('[Nginx serve] original_path=%s, proxito_path=%s, project=%s', - original_path, path, final_project.slug) + log.debug( + 'Nginx serve.', + original_path=original_path, + path=path, + ) content_type, encoding = mimetypes.guess_type(path) content_type = content_type or 'application/octet-stream' @@ -161,7 +164,7 @@ def _serve_docs_nginx(self, request, final_project, version_slug, path, download def _serve_401(self, request, project): res = render(request, '401.html') res.status_code = 401 - log.debug('Unauthorized access to %s documentation', project.slug) + log.debug('Unauthorized access to documentation.', project_slug=project.slug) return res def allowed_user(self, *args, **kwargs): @@ -171,8 +174,11 @@ def get_version_from_host(self, request, version_slug): # Handle external domain if hasattr(request, 'external_domain'): self.version_type = EXTERNAL - log.warning('Using version slug from host. url_version=%s host_version=%s', - version_slug, request.host_version_slug) + log.warning( + 'Using version slug from host.', + version_slug=version_slug, + host_version=request.host_version_slug, + ) version_slug = request.host_version_slug return version_slug @@ -201,7 +207,7 @@ def system_redirect(self, request, final_project, lang_slug, version_slug, filen query_params=urlparse_result.query, external=hasattr(request, 'external_domain'), ) - log.info('System Redirect: host=%s, from=%s, to=%s', request.get_host(), filename, to) + log.info('System Redirect.', host=request.get_host(), from_url=filename, to_url=to) resp = HttpResponseRedirect(to) resp['X-RTD-Redirect'] = 'system' return resp @@ -246,12 +252,12 @@ def canonical_redirect(self, request, final_project, version_slug, filename): if from_url == to: # check that we do have a response and avoid infinite redirect log.warning( - 'Infinite Redirect: FROM URL is the same than TO URL. url=%s', - to, + 'Infinite Redirect: FROM URL is the same than TO URL.', + url=to, ) raise InfiniteRedirectException() - log.info('Canonical Redirect: host=%s, from=%s, to=%s', request.get_host(), filename, to) + log.info('Canonical Redirect.', host=request.get_host(), from_url=filename, to_url=to) resp = HttpResponseRedirect(to) resp['X-RTD-Redirect'] = getattr(request, 'canonicalize', 'unknown') return resp @@ -289,17 +295,17 @@ def get_redirect_response(self, request, redirect_path, proxito_path, http_statu # However, if the new_path is already an absolute URI, just use it new_path = request.build_absolute_uri(new_path) log.info( - 'Redirecting: from=%s to=%s http_status=%s', - request.build_absolute_uri(proxito_path), - new_path, - http_status, + 'Redirecting...', + from_url=request.build_absolute_uri(proxito_path), + to_url=new_path, + http_status_code=http_status, ) if request.build_absolute_uri(proxito_path) == new_path: # check that we do have a response and avoid infinite redirect log.warning( - 'Infinite Redirect: FROM URL is the same than TO URL. url=%s', - new_path, + 'Infinite Redirect: FROM URL is the same than TO URL.', + url=new_path, ) raise InfiniteRedirectException() diff --git a/readthedocs/proxito/views/serve.py b/readthedocs/proxito/views/serve.py index a9ef658c489..201db0600e1 100644 --- a/readthedocs/proxito/views/serve.py +++ b/readthedocs/proxito/views/serve.py @@ -1,7 +1,7 @@ """Views for doc serving.""" import itertools -import logging +import structlog from urllib.parse import urlparse from readthedocs.core.resolver import resolve_path @@ -26,7 +26,7 @@ from .mixins import ServeDocsMixin, ServeRedirectMixin from .utils import _get_project_data_from_request -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa class ServePageRedirect(ServeRedirectMixin, ServeDocsMixin, View): @@ -78,10 +78,14 @@ def get(self, filename=filename, ) - log.debug( - 'Serving docs: project=%s, subproject=%s, lang_slug=%s, version_slug=%s, filename=%s', - final_project.slug, subproject_slug, lang_slug, version_slug, filename + log.bind( + project_slug=final_project.slug, + subproject_slug=subproject_slug, + lang_slug=lang_slug, + version_slug=version_slug, + filename=filename, ) + log.debug('Serving docs.') # Verify if the project is marked as spam and return a 401 in that case spam_response = self._spam_response(request, final_project) @@ -123,8 +127,8 @@ def get(self, self.version_type != EXTERNAL, ]): log.warning( - 'Invalid URL for project with versions. url=%s, project=%s', - filename, final_project.slug + 'Invalid URL for project with versions.', + filename=filename, ) raise Http404('Invalid URL for project with versions') @@ -195,7 +199,8 @@ def get(self, request, proxito_path, template_name='404.html'): the Docs default page (Maze Found) is rendered by Django and served. """ # pylint: disable=too-many-locals - log.info('Executing 404 handler. proxito_path=%s', proxito_path) + log.bind(proxito_path=proxito_path) + log.debug('Executing 404 handler.') # Parse the URL using the normal urlconf, so we get proper subdomain/translation data _, __, kwargs = url_resolve( @@ -214,6 +219,11 @@ def get(self, request, proxito_path, template_name='404.html'): filename=kwargs.get('filename', ''), ) + log.bind( + project_slug=final_project.slug, + version_slug=version_slug, + ) + storage_root_path = final_project.get_storage_path( type_='html', version_slug=version_slug, @@ -227,19 +237,9 @@ def get(self, request, proxito_path, template_name='404.html'): storage_root_path, f'{filename}/{tryfile}'.lstrip('/'), ) - log.debug( - 'Trying index filename: project=%s version=%s, file=%s', - final_project.slug, - version_slug, - storage_filename_path, - ) + log.debug('Trying index filename.') if build_media_storage.exists(storage_filename_path): - log.info( - 'Redirecting to index file: project=%s version=%s, storage_path=%s', - final_project.slug, - version_slug, - storage_filename_path, - ) + log.info('Redirecting to index file.') # Use urlparse so that we maintain GET args in our redirect parts = urlparse(proxito_path) if tryfile == 'README.html': @@ -327,9 +327,9 @@ def get(self, request, proxito_path, template_name='404.html'): storage_filename_path = build_media_storage.join(storage_root_path, tryfile) if build_media_storage.exists(storage_filename_path): log.info( - 'Serving custom 404.html page: [project: %s] [version: %s]', - final_project.slug, - version_slug_404, + 'Serving custom 404.html page.', + version_slug_404=version_slug_404, + storage_filename_path=storage_filename_path, ) resp = HttpResponse(build_media_storage.open(storage_filename_path).read()) resp.status_code = 404 diff --git a/readthedocs/proxito/views/utils.py b/readthedocs/proxito/views/utils.py index 1300c250d7f..5d6a8fbcf24 100644 --- a/readthedocs/proxito/views/utils.py +++ b/readthedocs/proxito/views/utils.py @@ -1,12 +1,12 @@ import os -import logging +import structlog from django.http import HttpResponse from django.shortcuts import get_object_or_404, render from .decorators import map_project_slug, map_subproject_slug -log = logging.getLogger(__name__) # noqa +log = structlog.get_logger(__name__) # noqa def fast_404(request, *args, **kwargs): @@ -61,8 +61,8 @@ def _get_project_data_from_request( filename = os.path.join(lang_slug, version_slug, filename) log.warning( 'URL looks like versioned on a single version project.' - 'Changing filename to match. filename=%s', - filename + 'Changing filename to match.', + filename=filename, ) lang_slug = version_slug = None diff --git a/readthedocs/redirects/models.py b/readthedocs/redirects/models.py index 19562ebf3ab..d1e509801e8 100644 --- a/readthedocs/redirects/models.py +++ b/readthedocs/redirects/models.py @@ -2,7 +2,7 @@ """Django models for the redirects app.""" -import logging +import structlog import re from django.db import models @@ -15,7 +15,7 @@ from .querysets import RedirectQuerySet -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) HTTP_STATUS_CHOICES = ( (301, _('301 - Permanent Redirect')), @@ -174,7 +174,7 @@ def get_redirect_path(self, path, language=None, version_slug=None): def redirect_prefix(self, path, language=None, version_slug=None): if path.startswith(self.from_url): - log.debug('Redirecting %s', self) + log.debug('Redirecting...', redirect=self) cut_path = re.sub('^%s' % self.from_url, '', path) to = self.get_full_path( @@ -187,7 +187,7 @@ def redirect_prefix(self, path, language=None, version_slug=None): def redirect_page(self, path, language=None, version_slug=None): if path == self.from_url: - log.debug('Redirecting %s', self) + log.debug('Redirecting...', redirect=self) to = self.get_full_path( filename=self.to_url.lstrip('/'), language=language, @@ -202,7 +202,7 @@ def redirect_exact(self, path, language=None, version_slug=None): # reconstruct the full path for an exact redirect full_path = self.get_full_path(path, language, version_slug, allow_crossdomain=False) if full_path == self.from_url: - log.debug('Redirecting %s', self) + log.debug('Redirecting...', redirect=self) return self.to_url # Handle full sub-level redirects if '$rest' in self.from_url: @@ -214,7 +214,7 @@ def redirect_exact(self, path, language=None, version_slug=None): def redirect_sphinx_html(self, path, language=None, version_slug=None): for ending in ['/', '/index.html']: if path.endswith(ending): - log.debug('Redirecting %s', self) + log.debug('Redirecting...', redirect=self) path = path[1:] # Strip leading slash. to = re.sub(ending + '$', '.html', path) return self.get_full_path( @@ -226,7 +226,7 @@ def redirect_sphinx_html(self, path, language=None, version_slug=None): def redirect_sphinx_htmldir(self, path, language=None, version_slug=None): if path.endswith('.html'): - log.debug('Redirecting %s', self) + log.debug('Redirecting...', redirect=self) path = path[1:] # Strip leading slash. to = re.sub('.html$', '/', path) return self.get_full_path( diff --git a/readthedocs/redirects/querysets.py b/readthedocs/redirects/querysets.py index b944e0ef271..968644ec7dc 100644 --- a/readthedocs/redirects/querysets.py +++ b/readthedocs/redirects/querysets.py @@ -1,12 +1,12 @@ """Queryset for the redirects app.""" -import logging +import structlog from django.db import models from django.db.models import CharField, F, Q, Value from readthedocs.core.permissions import AdminPermission -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class RedirectQuerySet(models.QuerySet): diff --git a/readthedocs/redirects/utils.py b/readthedocs/redirects/utils.py index f0698fdb21c..2f1ec2ae99a 100644 --- a/readthedocs/redirects/utils.py +++ b/readthedocs/redirects/utils.py @@ -7,7 +7,7 @@ These are not used directly as views; they are instead included into 404 handlers, so that redirects only take effect if no other view matches. """ -import logging +import structlog import re from urllib.parse import urlparse, urlunparse @@ -17,7 +17,7 @@ from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def project_and_path_from_request(request, path): diff --git a/readthedocs/rtd_tests/base.py b/readthedocs/rtd_tests/base.py index b8b1f8e95d9..2eb0ec01fe8 100644 --- a/readthedocs/rtd_tests/base.py +++ b/readthedocs/rtd_tests/base.py @@ -1,5 +1,5 @@ """Base classes and mixins for unit tests.""" -import logging +import structlog from collections import OrderedDict from unittest.mock import patch @@ -8,7 +8,7 @@ from django.contrib.sessions.middleware import SessionMiddleware from django.test import RequestFactory, TestCase -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class RequestFactoryTestMixin: diff --git a/readthedocs/rtd_tests/tests/test_build_notifications.py b/readthedocs/rtd_tests/tests/test_build_notifications.py index 3ef8c3a0e58..9dc9a3a8145 100644 --- a/readthedocs/rtd_tests/tests/test_build_notifications.py +++ b/readthedocs/rtd_tests/tests/test_build_notifications.py @@ -43,8 +43,8 @@ def test_send_notification_none_if_wrong_version_pk(self, mock_logger): event=WebHookEvent.BUILD_FAILED, ) mock_logger.warning.assert_called_with( - 'Version not found for given kwargs. %s', - {'pk': 345343}, + 'Version not found for given kwargs.', + kwargs={'pk': 345343}, ) def test_send_notification_none(self): diff --git a/readthedocs/rtd_tests/tests/test_celery.py b/readthedocs/rtd_tests/tests/test_celery.py index cb9e5ac1bb7..c9b351a2668 100644 --- a/readthedocs/rtd_tests/tests/test_celery.py +++ b/readthedocs/rtd_tests/tests/test_celery.py @@ -343,8 +343,8 @@ def test_fileify_logging_when_wrong_version_pk(self, mock_logger): search_ignore=[], ) mock_logger.warning.assert_called_with( - 'Version not found for given kwargs. %s', - {'pk': 345343}, + 'Version not found for given kwargs.', + kwargs={'pk': 345343}, ) @patch('readthedocs.oauth.services.github.GitHubService.send_build_status') diff --git a/readthedocs/rtd_tests/tests/test_oauth.py b/readthedocs/rtd_tests/tests/test_oauth.py index 7a361f186ee..dd77676fc91 100644 --- a/readthedocs/rtd_tests/tests/test_oauth.py +++ b/readthedocs/rtd_tests/tests/test_oauth.py @@ -192,9 +192,9 @@ def test_send_build_status_successful(self, session, mock_logger): self.assertTrue(success) mock_logger.info.assert_called_with( - "GitHub commit status created for project: %s, commit status: %s", - self.project.slug, - BUILD_STATUS_SUCCESS + "GitHub commit status created for project.", + project_slug=self.project.slug, + commit_status=BUILD_STATUS_SUCCESS ) @mock.patch('readthedocs.oauth.services.github.log') @@ -209,12 +209,11 @@ def test_send_build_status_404_error(self, session, mock_logger): self.assertFalse(success) mock_logger.info.assert_called_with( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s, user=%s, status=%s, url=%s', - self.project.slug, - self.user.username, - 404, - 'https://api.github.com/repos/pypa/pip/statuses/1234' + 'GitHub project does not exist or user does not have permissions.', + project_slug=self.project.slug, + user_username=self.user.username, + http_status_code=404, + statuses_url='https://api.github.com/repos/pypa/pip/statuses/1234' ) @mock.patch('readthedocs.oauth.services.github.log') @@ -227,8 +226,8 @@ def test_send_build_status_value_error(self, session, mock_logger): self.assertFalse(success) mock_logger.exception.assert_called_with( - 'GitHub commit status creation failed for project: %s', - self.project.slug, + 'GitHub commit status creation failed for project.', + project_slug=self.project.slug, ) @override_settings(DEFAULT_PRIVACY_LEVEL='private') @@ -265,8 +264,8 @@ def test_setup_webhook_successful(self, session, mock_logger): self.assertTrue(success) self.assertIsNotNone(self.integration.secret) mock_logger.info.assert_called_with( - "GitHub webhook creation successful for project: %s", - self.project, + "GitHub webhook creation successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -282,9 +281,8 @@ def test_setup_webhook_404_error(self, session, mock_logger): self.assertFalse(success) self.assertIsNone(self.integration.secret) mock_logger.info.assert_called_with( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'GitHub project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -300,8 +298,8 @@ def test_setup_webhook_value_error(self, session, mock_logger): self.assertIsNone(self.integration.secret) mock_logger.exception.assert_called_with( - 'GitHub webhook creation failed for project: %s', - self.project, + 'GitHub webhook creation failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -319,8 +317,8 @@ def test_update_webhook_successful(self, session, mock_logger): self.assertTrue(success) self.assertIsNotNone(self.integration.secret) mock_logger.info.assert_called_with( - "GitHub webhook update successful for project: %s", - self.project, + "GitHub webhook update successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.GitHubService.get_session') @@ -367,8 +365,8 @@ def test_update_webhook_value_error(self, session, mock_logger): self.assertIsNone(self.integration.secret) mock_logger.exception.assert_called_with( - 'GitHub webhook update failed for project: %s', - self.project, + 'GitHub webhook update failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -402,8 +400,8 @@ def test_get_provider_data_successful(self, session, mock_logger): self.assertEqual(self.integration.provider_data, webhook_data[0]) mock_logger.info.assert_called_with( - 'GitHub integration updated with provider data for project: %s', - self.project, + 'GitHub integration updated with provider data for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -423,9 +421,8 @@ def test_get_provider_data_404_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.info.assert_called_with( - 'GitHub project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'GitHub project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.github.log') @@ -445,8 +442,8 @@ def test_get_provider_data_attribute_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.exception.assert_called_with( - 'GitHub webhook Listing failed for project: %s', - self.project, + 'GitHub webhook Listing failed for project.', + project_slug=self.project.slug, ) @@ -700,8 +697,8 @@ def test_setup_webhook_successful(self, session, mock_logger): self.assertTrue(success) mock_logger.info.assert_called_with( - "Bitbucket webhook creation successful for project: %s", - self.project, + "Bitbucket webhook creation successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -715,9 +712,8 @@ def test_setup_webhook_404_error(self, session, mock_logger): self.assertFalse(success) mock_logger.info.assert_called_with( - 'Bitbucket project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'Bitbucket project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -730,8 +726,8 @@ def test_setup_webhook_value_error(self, session, mock_logger): ) mock_logger.exception.assert_called_with( - 'Bitbucket webhook creation failed for project: %s', - self.project, + 'Bitbucket webhook creation failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -747,8 +743,8 @@ def test_update_webhook_successful(self, session, mock_logger): self.assertTrue(success) self.assertIsNotNone(self.integration.secret) mock_logger.info.assert_called_with( - "Bitbucket webhook update successful for project: %s", - self.project, + "Bitbucket webhook update successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.BitbucketService.get_session') @@ -792,8 +788,8 @@ def test_update_webhook_value_error(self, session, mock_logger): ) mock_logger.exception.assert_called_with( - 'Bitbucket webhook update failed for project: %s', - self.project, + 'Bitbucket webhook update failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -827,8 +823,8 @@ def test_get_provider_data_successful(self, session, mock_logger): self.assertEqual(self.integration.provider_data, webhook_data['values'][0]) mock_logger.info.assert_called_with( - 'Bitbucket integration updated with provider data for project: %s', - self.project, + 'Bitbucket integration updated with provider data for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -848,9 +844,8 @@ def test_get_provider_data_404_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.info.assert_called_with( - 'Bitbucket project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'Bitbucket project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.bitbucket.log') @@ -870,8 +865,8 @@ def test_get_provider_data_attribute_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.exception.assert_called_with( - 'Bitbucket webhook Listing failed for project: %s', - self.project, + 'Bitbucket webhook Listing failed for project.', + project_slug=self.project.slug, ) @@ -1092,9 +1087,9 @@ def test_send_build_status_successful(self, repo_id, session, mock_logger): self.assertTrue(success) mock_logger.info.assert_called_with( - "GitLab commit status created for project: %s, commit status: %s", - self.project.slug, - BUILD_STATUS_SUCCESS + "GitLab commit status created for project.", + project_slug=self.project.slug, + commit_status=BUILD_STATUS_SUCCESS ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1112,12 +1107,11 @@ def test_send_build_status_404_error(self, repo_id, session, mock_logger): self.assertFalse(success) mock_logger.info.assert_called_with( - 'GitLab project does not exist or user does not have permissions: ' - 'project=%s, user=%s, status=%s, url=%s', - self.project.slug, - self.user.username, - 404, - 'https://gitlab.com/api/v4/projects/9999/statuses/1234', + 'GitLab project does not exist or user does not have permissions.', + project_slug=self.project.slug, + user_username=self.user.username, + http_status_code=404, + statuses_url='https://gitlab.com/api/v4/projects/9999/statuses/1234', ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1133,8 +1127,8 @@ def test_send_build_status_value_error(self, repo_id, session, mock_logger): self.assertFalse(success) mock_logger.exception.assert_called_with( - 'GitLab commit status creation failed for project: %s', - self.project.slug, + 'GitLab commit status creation failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1152,8 +1146,8 @@ def test_setup_webhook_successful(self, session, mock_logger): self.assertTrue(success) self.assertIsNotNone(self.integration.secret) mock_logger.info.assert_called_with( - "GitLab webhook creation successful for project: %s", - self.project, + "GitLab webhook creation successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1170,9 +1164,8 @@ def test_setup_webhook_404_error(self, session, mock_logger): self.assertFalse(success) self.assertIsNone(self.integration.secret) mock_logger.info.assert_called_with( - 'Gitlab project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'Gitlab project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1188,8 +1181,9 @@ def test_setup_webhook_value_error(self, session, mock_logger): self.assertIsNone(self.integration.secret) mock_logger.exception.assert_called_with( - 'GitLab webhook creation failed for project: %s', - self.project, + 'GitLab webhook creation failed for project.', + project_slug=self.project.slug + , ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1209,8 +1203,8 @@ def test_update_webhook_successful(self, repo_id, session, mock_logger): self.assertTrue(success) self.assertIsNotNone(self.integration.secret) mock_logger.info.assert_called_with( - "GitLab webhook update successful for project: %s", - self.project, + "GitLab webhook update successful for project.", + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.GitLabService.get_session') @@ -1263,8 +1257,8 @@ def test_update_webhook_value_error(self, repo_id, session, mock_logger): self.assertIsNone(self.integration.secret) mock_logger.exception.assert_called_with( - 'GitLab webhook update failed for project: %s', - self.project, + 'GitLab webhook update failed for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1298,8 +1292,8 @@ def test_get_provider_data_successful(self, session, mock_logger): self.assertEqual(self.integration.provider_data, webhook_data[0]) mock_logger.info.assert_called_with( - 'GitLab integration updated with provider data for project: %s', - self.project, + 'GitLab integration updated with provider data for project.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1319,9 +1313,8 @@ def test_get_provider_data_404_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.info.assert_called_with( - 'GitLab project does not exist or user does not have ' - 'permissions: project=%s', - self.project, + 'GitLab project does not exist or user does not have permissions.', + project_slug=self.project.slug, ) @mock.patch('readthedocs.oauth.services.gitlab.log') @@ -1341,6 +1334,6 @@ def test_get_provider_data_attribute_error(self, session, mock_logger): self.assertEqual(self.integration.provider_data, {}) mock_logger.exception.assert_called_with( - 'GitLab webhook Listing failed for project: %s', - self.project, + 'GitLab webhook Listing failed for project.', + project_slug=self.project.slug, ) diff --git a/readthedocs/rtd_tests/tests/test_privacy.py b/readthedocs/rtd_tests/tests/test_privacy.py index d650befc02d..54fda4affbd 100644 --- a/readthedocs/rtd_tests/tests/test_privacy.py +++ b/readthedocs/rtd_tests/tests/test_privacy.py @@ -1,4 +1,4 @@ -import logging +import structlog from unittest import mock from django.contrib.auth.models import User @@ -10,7 +10,7 @@ from readthedocs.projects.forms import UpdateProjectForm from readthedocs.projects.models import Project -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) @mock.patch('readthedocs.projects.tasks.clean_build', new=mock.MagicMock) @@ -32,9 +32,10 @@ def _create_kong( ): self.client.login(username='eric', password='test') log.info( - 'Making kong with privacy: %s and version privacy: %s', - privacy_level, - version_privacy_level, + 'Changing project privacy level.', + project_slug='django-kong', + project_privacy_level=privacy_level, + version_privacy_level=version_privacy_level, ) # Create project via project form, simulate import wizard without magic form = UpdateProjectForm( diff --git a/readthedocs/rtd_tests/tests/test_redirects.py b/readthedocs/rtd_tests/tests/test_redirects.py index abfabfcaf76..ac58efa6bcb 100644 --- a/readthedocs/rtd_tests/tests/test_redirects.py +++ b/readthedocs/rtd_tests/tests/test_redirects.py @@ -1,5 +1,3 @@ -import logging - from django.http import Http404 from django.test import TestCase from django.test.utils import override_settings @@ -20,7 +18,6 @@ class RedirectTests(TestCase): fixtures = ['eric', 'test_data'] def setUp(self): - logging.disable(logging.DEBUG) self.client.login(username='eric', password='test') pip = Project.objects.get(slug='pip') pip.versions.create_latest() diff --git a/readthedocs/rtd_tests/utils.py b/readthedocs/rtd_tests/utils.py index a03c27a0db2..02ed03cea33 100644 --- a/readthedocs/rtd_tests/utils.py +++ b/readthedocs/rtd_tests/utils.py @@ -1,6 +1,6 @@ """Utility functions for use in tests.""" -import logging +import structlog import subprocess import textwrap from os import chdir, environ, mkdir @@ -14,7 +14,7 @@ from readthedocs.doc_builder.base import restoring_chdir -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def get_readthedocs_app_path(): diff --git a/readthedocs/search/api.py b/readthedocs/search/api.py index df00f527092..7e1d8730367 100644 --- a/readthedocs/search/api.py +++ b/readthedocs/search/api.py @@ -1,4 +1,4 @@ -import logging +import structlog from functools import lru_cache, namedtuple from math import ceil @@ -18,7 +18,7 @@ from .serializers import PageSearchSerializer, ProjectData, VersionData -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class PaginatorPage: diff --git a/readthedocs/search/documents.py b/readthedocs/search/documents.py index 32309911648..0a401c8befc 100644 --- a/readthedocs/search/documents.py +++ b/readthedocs/search/documents.py @@ -1,4 +1,4 @@ -import logging +import structlog from django.conf import settings from django_elasticsearch_dsl import Document, Index, fields @@ -14,7 +14,7 @@ page_index = Index(page_conf['name']) page_index.settings(**page_conf['settings']) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class RTDDocTypeMixin: diff --git a/readthedocs/search/faceted_search.py b/readthedocs/search/faceted_search.py index 16c62a7ebf2..4dfb8b0622f 100644 --- a/readthedocs/search/faceted_search.py +++ b/readthedocs/search/faceted_search.py @@ -1,4 +1,4 @@ -import logging +import structlog import re from django.conf import settings @@ -18,7 +18,7 @@ from readthedocs.search.documents import PageDocument, ProjectDocument -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) ALL_FACETS = ['project', 'version', 'role_name', 'language'] diff --git a/readthedocs/search/management/commands/reindex_elasticsearch.py b/readthedocs/search/management/commands/reindex_elasticsearch.py index b4fcf7d30df..8b25212a02a 100644 --- a/readthedocs/search/management/commands/reindex_elasticsearch.py +++ b/readthedocs/search/management/commands/reindex_elasticsearch.py @@ -1,5 +1,5 @@ import itertools -import logging +import structlog import sys import textwrap from datetime import datetime, timedelta @@ -17,7 +17,7 @@ switch_es_index, ) -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Command(BaseCommand): @@ -39,13 +39,13 @@ def _get_indexing_tasks(app_label, model_name, index_name, queryset, document_cl if not objects_id: break current += len(objects_id) - log.info('Total: %s', current) + log.info('Total.', total=current) data['objects_id'] = objects_id yield index_objects_to_es.si(**data) def _run_reindex_tasks(self, models, queue): apply_async_kwargs = {'queue': queue} - log.info('Adding indexing tasks to queue %s', queue) + log.info('Adding indexing tasks to queue.', queue=queue) timestamp = datetime.now().strftime('%Y%m%d%H%M%S') @@ -66,7 +66,7 @@ def _run_reindex_tasks(self, models, queue): new_index_name=new_index_name, ) doc._index._name = new_index_name - log.info('Temporal index created: %s', new_index_name) + log.info('Temporal index created.', index_name=new_index_name) indexing_tasks = self._get_indexing_tasks( app_label=app_label, @@ -79,8 +79,10 @@ def _run_reindex_tasks(self, models, queue): task.apply_async(**apply_async_kwargs) log.info( - "Tasks issued successfully. model=%s.%s items=%s", - app_label, model_name, str(queryset.count()) + "Tasks issued successfully.", + model_name=model_name, + app_label=app_label, + items=queryset.count(), ) return timestamp @@ -98,8 +100,11 @@ def _change_index(self, models, timestamp): new_index_name=new_index_name, ) log.info( - "Index name changed. model=%s.%s from=%s to=%s", - app_label, model_name, new_index_name, index_name, + "Index name changed.", + app_label=app_label, + model_name=model_name, + new_index_name=new_index_name, + index_name=index_name, ) def _reindex_from(self, days_ago, models, queue): @@ -110,7 +115,7 @@ def _reindex_from(self, days_ago, models, queue): models = models or functions.keys() for model in models: if model not in functions: - log.warning("Re-index from not available for model %s", model.__name__) + log.warning("Re-index from not available for model.", model_name=model.__name__) continue functions[model](days_ago=days_ago, queue=queue) @@ -133,8 +138,10 @@ def _reindex_projects_from(self, days_ago, queue): for task in indexing_tasks: task.apply_async(**apply_async_kwargs) log.info( - "Tasks issued successfully. model=%s.%s items=%s", - app_label, model_name, str(queryset.count()) + "Tasks issued successfully.", + app_label=app_label, + model_name=model_name, + items=queryset.count(), ) def _reindex_files_from(self, days_ago, queue): @@ -169,15 +176,19 @@ def _reindex_files_from(self, days_ago, queue): break current += len(objects_id) log.info( - 'Re-indexing files. version=%s:%s total=%s', - project.slug, version.slug, current, + 'Re-indexing files.', + version_slug=version.slug, + project_slug=project.slug, + items=current, ) apply_async_kwargs['kwargs']['objects_id'] = objects_id index_objects_to_es.apply_async(**apply_async_kwargs) log.info( - "Tasks issued successfully. version=%s:%s items=%s", - project.slug, version.slug, str(current), + "Tasks issued successfully.", + project_slug=project.slug, + version_slug=version.slug, + items=current, ) def add_arguments(self, parser): diff --git a/readthedocs/search/parsers.py b/readthedocs/search/parsers.py index 7a1af27bb26..245e21c0021 100644 --- a/readthedocs/search/parsers.py +++ b/readthedocs/search/parsers.py @@ -1,7 +1,7 @@ """JSON/HTML parsers for search indexing.""" import itertools -import logging +import structlog import os import re from urllib.parse import urlparse @@ -11,7 +11,7 @@ from readthedocs.storage import build_media_storage -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class BaseParser: @@ -38,8 +38,8 @@ def _get_page_content(self, page): content = f.read() except Exception: log.warning( - 'Unhandled exception during search processing file: %s', - page, + 'Unhandled exception during search processing file.', + page=page, ) return content @@ -126,7 +126,7 @@ def _parse_sections(self, title, body): 'content': content, } except Exception as e: - log.info('Unable to index section: %s', str(e)) + log.info('Unable to index section', section=str(e)) # Index content from h1 to h6 headers. for head_level in range(1, 7): @@ -141,7 +141,7 @@ def _parse_sections(self, title, body): 'content': content, } except Exception as e: - log.info('Unable to index section: %s', str(e)) + log.info('Unable to index section.', section=str(e)) def _get_sections(self, title, body): """Get the first `self.max_inner_documents` sections.""" @@ -153,8 +153,10 @@ def _get_sections(self, title, body): pass else: log.warning( - 'Limit of inner sections exceeded. project=%s version=%s limit=%d', - self.project.slug, self.version.slug, self.max_inner_documents, + 'Limit of inner sections exceeded.', + project_slug=self.project.slug, + version_slug=self.version.slug, + limit=self.max_inner_documents, ) return sections @@ -343,8 +345,8 @@ def parse(self, page): return self._process_fjson(fjson_path) except Exception: log.warning( - 'Unhandled exception during search processing file: %s', - fjson_path, + 'Unhandled exception during search processing file.', + path=fjson_path, ) return { @@ -360,7 +362,7 @@ def _process_fjson(self, fjson_path): with self.storage.open(fjson_path, mode='r') as f: file_contents = f.read() except IOError: - log.info('Unable to read file: %s', fjson_path) + log.info('Unable to read file.', path=fjson_path) raise data = json.loads(file_contents) @@ -372,29 +374,29 @@ def _process_fjson(self, fjson_path): if 'current_page_name' in data: path = data['current_page_name'] else: - log.info('Unable to index file due to no name %s', fjson_path) + log.info('Unable to index file due to no name.', path=fjson_path) if 'title' in data: title = data['title'] title = HTMLParser(title).text().strip() else: - log.info('Unable to index title for: %s', fjson_path) + log.info('Unable to index title.', path=fjson_path) if 'body' in data: try: body = HTMLParser(data['body']) sections = self._get_sections(title=title, body=body.body) except Exception as e: - log.info('Unable to index sections for: %s', fjson_path) + log.info('Unable to index sections.', path=fjson_path) try: # Create a new html object, since the previous one could have been modified. body = HTMLParser(data['body']) domain_data = self._generate_domains_data(body) except Exception as e: - log.info('Unable to index domains for: %s', fjson_path) + log.info('Unable to index domains.', path=fjson_path) else: - log.info('Unable to index content for: %s', fjson_path) + log.info('Unable to index content.', path=fjson_path) return { 'path': path, @@ -469,8 +471,10 @@ def _generate_domains_data(self, body): number_of_domains += 1 if number_of_domains >= self.max_inner_documents: log.warning( - 'Limit of inner domains exceeded. project=%s version=%s limit=%i', - self.project.slug, self.version.slug, self.max_inner_documents, + 'Limit of inner domains exceeded.', + project_slug=self.project.slug, + version_slug=self.version.slug, + limit=self.max_inner_documents, ) break except Exception: @@ -513,7 +517,7 @@ def parse_from_html(self, page): if content: return self._process_content(page, content) except Exception as e: - log.info('Failed to index page %s, %s', page, str(e)) + log.info('Failed to index page.', path=page, exception=str(e)) return { 'path': page, 'title': '', @@ -532,9 +536,8 @@ def _process_content(self, page, content): sections = self._get_sections(title=title, body=body) else: log.info( - 'Page doesn\'t look like it has valid content, skipping. ' - 'page=%s', - page, + "Page doesn't look like it has valid content, skipping.", + page=page, ) return { 'path': page, @@ -557,8 +560,8 @@ def parse_from_index_file(self, page): return index_data except Exception: log.warning( - 'Unhandled exception during search processing file: %s', - page, + 'Unhandled exception during search processing file.', + page=page, ) return { 'path': page, @@ -573,7 +576,7 @@ def _process_index_file(self, json_path, page): with self.storage.open(json_path, mode='r') as f: file_contents = f.read() except IOError: - log.info('Unable to read file: %s', json_path) + log.info('Unable to read file.', path=json_path) raise data = json.loads(file_contents) diff --git a/readthedocs/search/signals.py b/readthedocs/search/signals.py index ba571efd8bc..aed22f0b02a 100644 --- a/readthedocs/search/signals.py +++ b/readthedocs/search/signals.py @@ -1,5 +1,5 @@ """We define custom Django signals to trigger before executing searches.""" -import logging +import structlog from django.db.models.signals import post_save, pre_delete from django.dispatch import receiver @@ -9,7 +9,7 @@ from readthedocs.projects.models import Project from readthedocs.search.tasks import delete_objects_in_es, index_objects_to_es -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) @receiver(post_save, sender=Project) diff --git a/readthedocs/search/tasks.py b/readthedocs/search/tasks.py index aa7af857d19..8e6559cfce9 100644 --- a/readthedocs/search/tasks.py +++ b/readthedocs/search/tasks.py @@ -1,4 +1,4 @@ -import logging +import structlog from dateutil.parser import parse from django.apps import apps @@ -12,7 +12,7 @@ from .utils import _get_document, _get_index -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) @app.task(queue='web') @@ -47,15 +47,23 @@ def index_objects_to_es( # Hack the index name temporarily for reindexing tasks old_index_name = document._index._name document._index._name = index_name - log.info('Replacing index name %s with %s', old_index_name, index_name) - - log.info("Indexing model: %s, '%s' objects", model.__name__, queryset.count()) + log.info( + 'Replacing index name.', + old_index_name=old_index_name, + new_index_name=index_name,) + + log.info( + "Indexing model.", + model=model.__name__, + count=queryset.count(), + ) doc_obj.update(queryset.iterator()) if index_name: log.info( - 'Undoing index replacement, settings %s with %s', - document._index._name, old_index_name, + 'Undoing index replacement.', + old_index_name=document._index._name, + new_index_name=old_index_name, ) document._index._name = old_index_name @@ -67,7 +75,11 @@ def delete_objects_in_es(app_label, model_name, document_class, objects_id): doc_obj = document() queryset = doc_obj.get_queryset() queryset = queryset.filter(id__in=objects_id) - log.info("Deleting model: %s, '%s' objects", model.__name__, queryset.count()) + log.info( + "Deleting model.", + model=model.__name__, + count=queryset.count(), + ) try: # This is a common case that we should be handling a better way doc_obj.update(queryset.iterator(), action='delete') @@ -123,7 +135,7 @@ def index_missing_objects(app_label, model_name, document_class, index_generatio queryset = document().get_queryset().exclude(**{query_string: index_generation_time}) document().update(queryset.iterator()) - log.info("Indexed %s missing objects from model: %s'", queryset.count(), model.__name__) + log.info("Indexed missing objects from model.", count=queryset.count(), model=model.__name__) # TODO: Figure out how to remove the objects from ES index that has been deleted @@ -142,7 +154,7 @@ def delete_old_search_queries_from_db(): ) if search_queries_qs.exists(): - log.info('Deleting search queries for last 3 months. Total: %s', search_queries_qs.count()) + log.info('Deleting search queries for last 3 months.', total=search_queries_qs.count()) search_queries_qs.delete() @@ -151,12 +163,12 @@ def record_search_query(project_slug, version_slug, query, total_results, time_s """Record/update a search query for analytics.""" if not project_slug or not version_slug or not query: log.debug( - 'Not recording the search query. Passed arguments: ' - 'project_slug: %s, version_slug: %s, query: %s, total_results: %s, time: %s', - project_slug, - version_slug, - query, total_results, - time_string + 'Not recording the search query.', + project_slug=project_slug, + version_slug=version_slug, + query=query, + total_results=total_results, + time=time_string, ) return @@ -186,9 +198,9 @@ def record_search_query(project_slug, version_slug, query, total_results, time_s ) if not version: log.debug( - 'Not recording the search query because project does not exist. ' - 'project=%s version=%s', - project_slug, version_slug, + 'Not recording the search query because project does not exist.', + project_slug=project_slug, + version_slug=version_slug, ) return diff --git a/readthedocs/search/utils.py b/readthedocs/search/utils.py index 6d7a56049b7..646d80b1d2c 100644 --- a/readthedocs/search/utils.py +++ b/readthedocs/search/utils.py @@ -1,6 +1,6 @@ """Utilities related to reading and generating indexable search content.""" -import logging +import structlog from django.utils import timezone from django_elasticsearch_dsl.apps import DEDConfig @@ -8,18 +8,19 @@ from readthedocs.projects.models import HTMLFile -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) def index_new_files(model, version, build): """Index new files from the version into the search index.""" + log.bind( + project_slug=version.project.slug, + version_slug=version.slug, + ) + if not DEDConfig.autosync_enabled(): - log.info( - 'Autosync disabled, skipping indexing into the search index for: %s:%s', - version.project.slug, - version.slug, - ) + log.info('Autosync disabled. Skipping indexing into the search index.') return try: @@ -29,11 +30,7 @@ def index_new_files(model, version, build): doc_obj.get_queryset() .filter(project=version.project, version=version, build=build) ) - log.info( - 'Indexing new objecst into search index for: %s:%s', - version.project.slug, - version.slug, - ) + log.info('Indexing new objecst into search index.') doc_obj.update(queryset.iterator()) except Exception: log.exception('Unable to index a subset of files. Continuing.') @@ -50,21 +47,18 @@ def remove_indexed_files(model, project_slug, version_slug=None, build_id=None): :param build_id: Build id. If isn't given, all index from `version` are deleted. """ + log.bind( + project_slug=project_slug, + version_slug=version_slug, + ) + if not DEDConfig.autosync_enabled(): - log.info( - 'Autosync disabled, skipping removal from the search index for: %s:%s', - project_slug, - version_slug, - ) + log.info('Autosync disabled, skipping removal from the search index.') return try: document = list(registry.get_documents(models=[model]))[0] - log.info( - 'Deleting old files from search index for: %s:%s', - project_slug, - version_slug, - ) + log.info('Deleting old files from search index.') documents = ( document().search() .filter('term', project=project_slug) diff --git a/readthedocs/search/views.py b/readthedocs/search/views.py index 083cf1f1004..758eee067de 100644 --- a/readthedocs/search/views.py +++ b/readthedocs/search/views.py @@ -1,6 +1,6 @@ """Search views.""" import collections -import logging +import structlog from django.conf import settings from django.shortcuts import get_object_or_404, render @@ -21,8 +21,7 @@ VersionData, ) -log = logging.getLogger(__name__) -LOG_TEMPLATE = '(Elastic Search) [%(user)s:%(type)s] [%(project)s:%(version)s:%(language)s] %(msg)s' +log = structlog.get_logger(__name__) UserInput = collections.namedtuple( 'UserInput', diff --git a/readthedocs/settings/base.py b/readthedocs/settings/base.py index 653726af0dd..772f48a3803 100644 --- a/readthedocs/settings/base.py +++ b/readthedocs/settings/base.py @@ -1,6 +1,5 @@ # pylint: disable=missing-docstring -import logging import os import subprocess import socket @@ -27,7 +26,7 @@ _ = gettext = lambda s: s -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class CommunityBaseSettings(Settings): @@ -252,6 +251,7 @@ def USE_PROMOS(self): # noqa 'django_permissions_policy.PermissionsPolicyMiddleware', 'simple_history.middleware.HistoryRequestMiddleware', 'readthedocs.core.logs.ReadTheDocsRequestMiddleware', + 'django_structlog.middlewares.CeleryMiddleware', ) AUTHENTICATION_BACKENDS = ( @@ -621,10 +621,10 @@ def DOCKER_LIMITS(self): ) } log.info( - 'Using dynamic docker limits. hostname=%s memory=%s time=%s', - socket.gethostname(), - limits['memory'], - limits['time'], + 'Using dynamic docker limits.', + hostname=socket.gethostname(), + memory=limits['memory'], + time=limits['time'], ) return limits @@ -814,7 +814,7 @@ def DOCKER_LIMITS(self): 'console': { 'level': 'INFO', 'class': 'logging.StreamHandler', - 'formatter': 'default', + 'formatter': 'plain_console', }, 'debug': { 'level': 'DEBUG', diff --git a/readthedocs/settings/proxito/base.py b/readthedocs/settings/proxito/base.py index 6d371ae9509..9c3867c4c88 100644 --- a/readthedocs/settings/proxito/base.py +++ b/readthedocs/settings/proxito/base.py @@ -5,9 +5,9 @@ but currently we have them to be able to run the site with the old middleware for a staged rollout of the proxito code. """ -import logging +import structlog -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class CommunityProxitoSettingsMixin: @@ -44,6 +44,6 @@ def MIDDLEWARE(self): # noqa if mw in classes: classes.remove(mw) else: - log.warning('Failed to remove middleware: %s', mw) + log.warning('Failed to remove middleware.', middleware=mw) return classes diff --git a/readthedocs/sso/admin.py b/readthedocs/sso/admin.py index 4ad48516d3a..3fa1229e012 100644 --- a/readthedocs/sso/admin.py +++ b/readthedocs/sso/admin.py @@ -1,5 +1,5 @@ """Admin interface for SSO models.""" -import logging +import structlog from django.contrib import admin, messages @@ -9,7 +9,7 @@ from .models import SSODomain, SSOIntegration -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class SSOIntegrationAdmin(admin.ModelAdmin): @@ -31,9 +31,9 @@ def resync_sso_user_accounts(self, request, queryset): # pylint: disable=no-sel for ssointegration in queryset.select_related('organization'): members = AdminPermission.members(ssointegration.organization) log.info( - 'Triggering SSO re-sync for organization. organization=%s users=%s', - ssointegration.organization.slug, - members.count(), + 'Triggering SSO re-sync for organization.', + organization_slug=ssointegration.organization.slug, + count=members.count(), ) users_count += members.count() for user in members: diff --git a/readthedocs/vcs_support/backends/git.py b/readthedocs/vcs_support/backends/git.py index e659fd96c1c..13b218ee10a 100644 --- a/readthedocs/vcs_support/backends/git.py +++ b/readthedocs/vcs_support/backends/git.py @@ -1,6 +1,6 @@ """Git-related utilities.""" -import logging +import structlog import re import git @@ -21,7 +21,7 @@ from readthedocs.vcs_support.base import BaseVCS, VCSVersion -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class Backend(BaseVCS): @@ -261,7 +261,7 @@ def tags(self): # blob object - use the `.object` property instead to access it # This is not a real tag for us, so we skip it # https://github.com/rtfd/readthedocs.org/issues/4440 - log.warning('Git tag skipped: %s', tag, exc_info=True) + log.warning('Git tag skipped.', tag=tag, exc_info=True) continue versions.append(VCSVersion(self, hexsha, str(tag))) diff --git a/readthedocs/vcs_support/base.py b/readthedocs/vcs_support/base.py index 0f2456a2ab1..b1cca5d4c81 100644 --- a/readthedocs/vcs_support/base.py +++ b/readthedocs/vcs_support/base.py @@ -1,5 +1,5 @@ """Base classes for VCS backends.""" -import logging +import structlog import os import shutil @@ -7,7 +7,7 @@ from readthedocs.projects.exceptions import RepositoryError -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class VCSVersion: diff --git a/readthedocs/vcs_support/utils.py b/readthedocs/vcs_support/utils.py index c0240f8cf05..5c32e7d79db 100644 --- a/readthedocs/vcs_support/utils.py +++ b/readthedocs/vcs_support/utils.py @@ -2,13 +2,13 @@ """Locking utilities.""" import errno -import logging +import structlog import os import stat import time -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class LockTimeout(Exception): @@ -37,47 +37,41 @@ def __init__(self, project, version, timeout=5, polling_interval=0.1): def __enter__(self): start = time.time() + log.bind( + project_slug=self.name, + ) while os.path.exists(self.fpath): lock_age = time.time() - os.stat(self.fpath)[stat.ST_MTIME] if lock_age > self.timeout: - log.debug( - 'Lock (%s): Force unlock, old lockfile', - self.name, - ) + log.debug('Force unlock, old lockfile.') os.remove(self.fpath) break - log.debug('Lock (%s): Locked, waiting..', self.name) + log.debug('Locked, waiting...') time.sleep(self.polling_interval) timesince = time.time() - start if timesince > self.timeout: - log.debug( - 'Lock (%s): Force unlock, timeout reached', - self.name, - ) + log.debug('Force unlock, timeout reached') os.remove(self.fpath) break log.debug( - '%s still locked after %.2f seconds; retry for %.2f' - ' seconds', - self.name, - timesince, - self.timeout, + 'Lock still locked after some time. Retrying in some seconds', + locked_time=timesince, + seconds=self.timeout, ) open(self.fpath, 'w').close() - log.debug('Lock (%s): Lock acquired', self.name) + log.debug('Lock acquired.') def __exit__(self, exc, value, tb): + log.bind(project_slug=self.name) + try: - log.debug('Lock (%s): Releasing', self.name) + log.debug('Releasing lock.') os.remove(self.fpath) except OSError as e: # We want to ignore "No such file or directory" and log any other # type of error. if e.errno != errno.ENOENT: - log.exception( - 'Lock (%s): Failed to release, ignoring...', - self.name, - ) + log.exception('Failed to release, ignoring...') class NonBlockingLock: @@ -105,13 +99,11 @@ def __init__(self, project, version, max_lock_age=None): def __enter__(self): path_exists = os.path.exists(self.fpath) + log.bind(project_slug=self.name) if path_exists and self.max_lock_age is not None: lock_age = time.time() - os.stat(self.fpath)[stat.ST_MTIME] if lock_age > self.max_lock_age: - log.debug( - 'Lock (%s): Force unlock, old lockfile', - self.name, - ) + log.debug('Force unlock, old lockfile') os.remove(self.fpath) else: raise LockTimeout( @@ -125,15 +117,15 @@ def __enter__(self): return self def __exit__(self, exc_type, exc_val, exc_tb): + log.bind(project_slug=self.name) try: - log.debug('Lock (%s): Releasing', self.name) + log.debug('Releasing lock.') os.remove(self.fpath) except (IOError, OSError) as e: # We want to ignore "No such file or directory" and log any other # type of error. if e.errno != errno.ENOENT: log.error( - 'Lock (%s): Failed to release, ignoring...', - self.name, + 'Failed to release, ignoring...', exc_info=True, ) diff --git a/readthedocs/worker.py b/readthedocs/worker.py index 69932bcf8c4..3e65936ea1b 100644 --- a/readthedocs/worker.py +++ b/readthedocs/worker.py @@ -5,6 +5,8 @@ from celery import Celery from django.conf import settings +from django_structlog.celery.steps import DjangoStructLogInitStep + def create_application(): """Create a Celery application using Django settings.""" @@ -16,6 +18,10 @@ def create_application(): application = Celery(settings.CELERY_APP_NAME) application.config_from_object('django.conf:settings') application.autodiscover_tasks(None) + + # A step to initialize django-structlog + application.steps['worker'].add(DjangoStructLogInitStep) + return application From 9b261abc8233c0539c4e32f2bfd2593a8b20c224 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Tue, 23 Nov 2021 19:51:59 +0100 Subject: [PATCH 2/7] Make logs from `logging.getLogger` to look better Logs coming from `logging.getLogger` (from other applications) have the same structure that the ones logged by us via `structlog`. --- common | 2 +- readthedocs/core/logs.py | 21 +++++++++++---------- readthedocs/settings/base.py | 17 +++++++++++++++-- readthedocs/settings/docker_compose.py | 6 ++++++ 4 files changed, 33 insertions(+), 13 deletions(-) diff --git a/common b/common index 1c6dcd76bdc..0f7a02b7b2a 160000 --- a/common +++ b/common @@ -1 +1 @@ -Subproject commit 1c6dcd76bdcf4c94ee992e201778fc31e0586e5f +Subproject commit 0f7a02b7b2a47beea91345065da212e21fbcc831 diff --git a/readthedocs/core/logs.py b/readthedocs/core/logs.py index 7e8bf9321f7..478c8876658 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -69,20 +69,21 @@ def __call__(self, logger, method_name, event_dict): event_dict.update(output) return event_dict +shared_processors = [ + structlog.processors.TimeStamper(fmt='iso'), + structlog.stdlib.add_logger_name, + structlog.stdlib.add_log_level, + structlog.stdlib.PositionalArgumentsFormatter(), + structlog.processors.StackInfoRenderer(), + structlog.processors.UnicodeDecoder(), +] structlog.configure( - processors=[ + processors=list([ 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.StackInfoRenderer(), - # Remove `format_exc_info` from your processor chain if you want pretty exceptions. - # structlog.processors.format_exc_info, - structlog.processors.UnicodeDecoder(), + *shared_processors, structlog.stdlib.ProcessorFormatter.wrap_for_formatter, - ], + ]), context_class=structlog.threadlocal.wrap_dict(dict), logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, diff --git a/readthedocs/settings/base.py b/readthedocs/settings/base.py index 772f48a3803..de43f56b002 100644 --- a/readthedocs/settings/base.py +++ b/readthedocs/settings/base.py @@ -8,6 +8,7 @@ from celery.schedules import crontab +from readthedocs.core.logs import shared_processors from readthedocs.core.settings import Settings from readthedocs.projects.constants import CELERY_LOW, CELERY_MEDIUM, CELERY_HIGH @@ -803,11 +804,23 @@ def DOCKER_LIMITS(self): # structlog "plain_console": { "()": structlog.stdlib.ProcessorFormatter, - "processor": structlog.dev.ConsoleRenderer(), + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + structlog.dev.ConsoleRenderer(), + ], + # Allows to add extra data to log entries generated via ``logging`` module + # See https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging + "foreign_pre_chain": shared_processors, }, "key_value": { "()": structlog.stdlib.ProcessorFormatter, - "processor": structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']), + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + structlog.processors.KeyValueRenderer(key_order=['timestamp', 'level', 'event', 'logger']), + ], + # Allows to add extra data to log entries generated via ``logging`` module + # See https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging + "foreign_pre_chain": shared_processors, }, }, 'handlers': { diff --git a/readthedocs/settings/docker_compose.py b/readthedocs/settings/docker_compose.py index fc074952a66..0bc97b9fce8 100644 --- a/readthedocs/settings/docker_compose.py +++ b/readthedocs/settings/docker_compose.py @@ -78,6 +78,12 @@ def RTD_EMBED_API_EXTERNAL_DOMAINS(self): def LOGGING(self): logging = super().LOGGING logging['loggers'].update({ + # Disable Django access requests logging (e.g. GET /path/to/url) + # https://github.com/django/django/blob/ca9872905559026af82000e46cde6f7dedc897b6/django/core/servers/basehttp.py#L24 + 'django.server': { + 'handlers': ['null'], + 'propagate': False, + }, # Disable S3 logging 'boto3': { 'handlers': ['null'], From b4891137c5f9ef8a86cd51dd24dd4732f752221f Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Tue, 23 Nov 2021 20:30:01 +0100 Subject: [PATCH 3/7] Lint --- readthedocs/core/logs.py | 1 + 1 file changed, 1 insertion(+) diff --git a/readthedocs/core/logs.py b/readthedocs/core/logs.py index 478c8876658..07bf9a634d5 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -69,6 +69,7 @@ def __call__(self, logger, method_name, event_dict): event_dict.update(output) return event_dict + shared_processors = [ structlog.processors.TimeStamper(fmt='iso'), structlog.stdlib.add_logger_name, From e04aa5e05eb7f8e54ea6bdc9a5a53bee0144cd01 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Wed, 24 Nov 2021 11:21:17 +0100 Subject: [PATCH 4/7] Colored console locally and plain console in production --- readthedocs/settings/base.py | 12 +++++++++++- readthedocs/settings/docker_compose.py | 1 + 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/readthedocs/settings/base.py b/readthedocs/settings/base.py index de43f56b002..47cb223a90e 100644 --- a/readthedocs/settings/base.py +++ b/readthedocs/settings/base.py @@ -806,7 +806,17 @@ def DOCKER_LIMITS(self): "()": structlog.stdlib.ProcessorFormatter, "processors": [ structlog.stdlib.ProcessorFormatter.remove_processors_meta, - structlog.dev.ConsoleRenderer(), + structlog.dev.ConsoleRenderer(colors=False), + ], + # Allows to add extra data to log entries generated via ``logging`` module + # See https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging + "foreign_pre_chain": shared_processors, + }, + "colored_console": { + "()": structlog.stdlib.ProcessorFormatter, + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + structlog.dev.ConsoleRenderer(colors=True), ], # Allows to add extra data to log entries generated via ``logging`` module # See https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging diff --git a/readthedocs/settings/docker_compose.py b/readthedocs/settings/docker_compose.py index 0bc97b9fce8..4b1c61af018 100644 --- a/readthedocs/settings/docker_compose.py +++ b/readthedocs/settings/docker_compose.py @@ -77,6 +77,7 @@ def RTD_EMBED_API_EXTERNAL_DOMAINS(self): @property def LOGGING(self): logging = super().LOGGING + logging['handlers']['console']['formatter'] = 'colored_console' logging['loggers'].update({ # Disable Django access requests logging (e.g. GET /path/to/url) # https://github.com/django/django/blob/ca9872905559026af82000e46cde6f7dedc897b6/django/core/servers/basehttp.py#L24 From e6941fe3a001c637541f88cc5d81a973b75fb6d5 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Thu, 25 Nov 2021 19:08:33 +0100 Subject: [PATCH 5/7] Use `SysLogProcessor` and `SysLogRenderer` to format the logs Use a custom renderer to match the structure we want: ``` %programname[%processid] [%level] %message [%logger:%linenumber] %structureddata ``` By default, rsyslog will prepend ``` %timestamp %hostname ``` and it will look exactly as we want. --- readthedocs/core/logs.py | 128 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 127 insertions(+), 1 deletion(-) diff --git a/readthedocs/core/logs.py b/readthedocs/core/logs.py index 07bf9a634d5..acc97cb39cf 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -1,4 +1,7 @@ +from io import StringIO + import structlog +from structlog.dev import _pad from django_structlog.middlewares.request import RequestMiddleware @@ -70,8 +73,131 @@ def __call__(self, logger, method_name, event_dict): return event_dict +class SysLogRenderer(structlog.dev.ConsoleRenderer): + def __call__(self, logger, name, event_dict): + sio = StringIO() + + # ``readthedocs`` as programname is required because it's used by + # syslog to filter messages and send them to different files. + # https://www.rsyslog.com/doc/master/configuration/properties.html#message-properties + sio.write("readthedocs") + + process_id = event_dict.pop("process_id", None) + if process_id is not None: + sio.write( + "[" + + str(process_id) + + "]" + ) + + # syslog tag delimiter + sio.write(": ") + + ts = event_dict.pop("timestamp", None) + if ts is not None: + sio.write( + # can be a number if timestamp is UNIXy + self._styles.timestamp + + str(ts) + + self._styles.reset + + " " + ) + + level = event_dict.pop("level", None) + if level is not None: + sio.write( + "[" + + self._level_to_color.get(level, "") + + _pad(level, self._longest_level) + + self._styles.reset + + "] " + ) + + # force event to str for compatibility with standard library + event = event_dict.pop("event", None) + if not isinstance(event, str): + event = str(event) + + if event_dict: + event = _pad(event, self._pad_event) + self._styles.reset + " " + else: + event += self._styles.reset + sio.write(self._styles.bright + event) + + logger_name = event_dict.pop("logger", None) + if logger_name is None: + logger_name = event_dict.pop("logger_name", None) + + line_number = event_dict.pop("line_number", None) + if logger_name is not None: + sio.write( + "[" + + self._styles.logger_name + + self._styles.bright + + logger_name + + self._styles.reset + + ":" + + str(line_number) + + "] " + ) + + stack = event_dict.pop("stack", None) + exc = event_dict.pop("exception", None) + exc_info = event_dict.pop("exc_info", None) + + event_dict_keys = event_dict.keys() + if self._sort_keys: + event_dict_keys = sorted(event_dict_keys) + + sio.write( + " ".join( + self._styles.kv_key + + key + + self._styles.reset + + "=" + + self._styles.kv_value + + self._repr(event_dict[key]) + + self._styles.reset + for key in event_dict_keys + ) + ) + + if stack is not None: + sio.write("\n" + stack) + if exc_info or exc is not None: + sio.write("\n\n" + "=" * 79 + "\n") + + if exc_info: + if not isinstance(exc_info, tuple): + exc_info = sys.exc_info() + + self._exception_formatter(sio, exc_info) + elif exc is not None: + if self._exception_formatter is not plain_traceback: + warnings.warn( + "Remove `format_exc_info` from your processor chain " + "if you want pretty exceptions." + ) + sio.write("\n" + exc) + + return sio.getvalue() + + +class SysLogProcessor: + + def __call__(self, logger, method_name, event_dict): + record = event_dict.get('_record', None) + if record is None: + return event_dict + + event_dict.update({ + 'process_id': record.process, + 'line_number': record.lineno, + }) + return event_dict + + shared_processors = [ - structlog.processors.TimeStamper(fmt='iso'), structlog.stdlib.add_logger_name, structlog.stdlib.add_log_level, structlog.stdlib.PositionalArgumentsFormatter(), From a465871730d9f84d78c912fc4b47a5dc7c5a0a72 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Thu, 25 Nov 2021 19:21:43 +0100 Subject: [PATCH 6/7] Missing imports --- readthedocs/core/logs.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/readthedocs/core/logs.py b/readthedocs/core/logs.py index acc97cb39cf..a863dc48b05 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -1,7 +1,10 @@ +import sys +import warnings + from io import StringIO import structlog -from structlog.dev import _pad +from structlog.dev import _pad, plain_traceback from django_structlog.middlewares.request import RequestMiddleware From 41b325ef6fa3e1d9f1db13a3231285333dc5ace7 Mon Sep 17 00:00:00 2001 From: Manuel Kaufmann Date: Thu, 25 Nov 2021 19:51:14 +0100 Subject: [PATCH 7/7] Ignore `request_started` and `request_finished` events --- readthedocs/settings/base.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/readthedocs/settings/base.py b/readthedocs/settings/base.py index 47cb223a90e..9aa3f3c6683 100644 --- a/readthedocs/settings/base.py +++ b/readthedocs/settings/base.py @@ -855,9 +855,8 @@ def DOCKER_LIMITS(self): # Always send from the root, handlers can filter levels 'level': 'INFO', }, - 'django_structlog': { + 'django_structlog.middlewares.request': { 'handlers': ['null'], - 'level': 'INFO', # Don't double log at the root logger for these. 'propagate': False, },