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/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..a863dc48b05 100644 --- a/readthedocs/core/logs.py +++ b/readthedocs/core/logs.py @@ -1,4 +1,10 @@ +import sys +import warnings + +from io import StringIO + import structlog +from structlog.dev import _pad, plain_traceback from django_structlog.middlewares.request import RequestMiddleware @@ -70,18 +76,144 @@ 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.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(), - 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/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..9aa3f3c6683 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 @@ -9,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 @@ -27,7 +27,7 @@ _ = gettext = lambda s: s -log = logging.getLogger(__name__) +log = structlog.get_logger(__name__) class CommunityBaseSettings(Settings): @@ -252,6 +252,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 +622,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 @@ -803,18 +804,40 @@ def DOCKER_LIMITS(self): # structlog "plain_console": { "()": structlog.stdlib.ProcessorFormatter, - "processor": structlog.dev.ConsoleRenderer(), + "processors": [ + structlog.stdlib.ProcessorFormatter.remove_processors_meta, + 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 + "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': { 'console': { 'level': 'INFO', 'class': 'logging.StreamHandler', - 'formatter': 'default', + 'formatter': 'plain_console', }, 'debug': { 'level': 'DEBUG', @@ -832,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, }, diff --git a/readthedocs/settings/docker_compose.py b/readthedocs/settings/docker_compose.py index fc074952a66..4b1c61af018 100644 --- a/readthedocs/settings/docker_compose.py +++ b/readthedocs/settings/docker_compose.py @@ -77,7 +77,14 @@ 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 + 'django.server': { + 'handlers': ['null'], + 'propagate': False, + }, # Disable S3 logging 'boto3': { 'handlers': ['null'], 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