Merge pull request #8705 from readthedocs/humitos/migrate-to-structlog

structlog: migrate application code to better logging

Author: ericholscher

common

@@ -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',

readthedocs/analytics/utils.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:

readthedocs/api/v2/client.py

@@ -1,6 +1,6 @@
-import logging
+import structlog
 
-log = logging.getLogger(__name__)
+log = structlog.get_logger(__name__)
 
 
 class CachedResponseMixin:

readthedocs/api/v2/mixins.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,
     )
 
 

readthedocs/api/v2/utils.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):

readthedocs/api/v2/views/footer_views.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')

readthedocs/api/v2/views/integrations.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)
 

readthedocs/api/v2/views/model_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 = (

readthedocs/api/v2/views/task_views.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):

readthedocs/audit/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):

readthedocs/builds/apps.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()

readthedocs/builds/automation_actions.py

@@ -1,12 +1,12 @@
-import logging
+import structlog
 
 from django.forms.widgets import HiddenInput
 from django.utils.translation import ugettext_lazy as _
 from django_filters import CharFilter, ChoiceFilter, FilterSet
 
 from readthedocs.builds.constants import BUILD_STATE_FINISHED
 
-log = logging.getLogger(__name__)
+log = structlog.get_logger(__name__)
 
 
 class BuildListFilter(FilterSet):

readthedocs/builds/filters.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):