structlog: migrate application code to better logging

Initial work to migrate our application to structlog for better logging, making
them compatible with New Relic's integration.

There are more work that can be done here to make it better. For example, more
usage of `log.bind` to avoid repetition. Besides, rewriting some log message and
reduce them to have more Canonical Log
Lines (https://www.structlog.org/en/stable/logging-best-practices.html#canonical-log-lines)
instead.

Author: humitos

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

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:

readthedocs/api/v2/mixins.py

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

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,
     )
 
 

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):

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')

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)
 

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 = (

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):

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):

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()

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