Update Cloudflare purging to use structlog idioms

This changes the logging statements (and corresponding tests) to bind
contextvars early (so they can be shared with multiple statements) and
structure the data appropriately instead of putting data into the
"event" message.

cloudflare/tests/test_cache_tag_purge.py

@@ -3,6 +3,7 @@
 from django.test import TestCase, override_settings
 from requests.exceptions import HTTPError, InvalidURL
 
+from common.tests.utils import capture_logs_with_contextvars
 from cloudflare.utils import purge_tags_from_cache, purge_all_from_cache
 
 
@@ -59,21 +60,27 @@ def test_cache_purge_all(self, requests_delete):
 
 @override_settings(WAGTAILFRONTENDCACHE=WAGTAILFRONTENDCACHE_SETTINGS)
 @patch('cloudflare.utils.requests.delete')
-@patch('cloudflare.utils.logger')
 class LoggingTestCase(TestCase):
-    def test_log__success(self, logger_mock, delete_mock):
+    def test_log__success(self, delete_mock):
         """
         If Cloudflare's API response OK on purge, info should be logged
         """
         # Mock a successful JSON response
         delete_mock.return_value.json.return_value = {'success': True}
-        purge_all_from_cache()
-        logger_mock.info.assert_called_once_with(
-            'Purged from CloudFlare with data: %s',
-            '{}'
+
+        with capture_logs_with_contextvars() as cap_logs:
+            purge_all_from_cache()
+        log_entry = cap_logs[0]
+        self.assertEqual(
+            log_entry,
+            {
+                'event': 'Purged from CloudFlare',
+                'log_level': 'info',
+                'cloudflare_request_data': '{}',
+            },
         )
 
-    def test_log__http_ok__cf_error(self, logger_mock, delete_mock):
+    def test_log__http_ok__cf_error(self, delete_mock):
         """
         If Clouflare's API response returns a successful HTTP response, but
         without success in the json, an error should be logged
@@ -83,15 +90,20 @@ def test_log__http_ok__cf_error(self, logger_mock, delete_mock):
             'success': False,
             'errors': [{'message': 'Cloudflare doesn\'t like you 😡'}]
         }
-        purge_all_from_cache()
-        logger_mock.error.assert_called_once_with(
-            'Couldn\'t purge from Cloudflare with data: %s. '
-            'Cloudflare errors \'%s\'',
-            '{}',
-            'Cloudflare doesn\'t like you 😡'
+        with capture_logs_with_contextvars() as cap_logs:
+            purge_all_from_cache()
+        log_entry = cap_logs[0]
+        self.assertEqual(
+            log_entry,
+            {
+                'event': "Couldn't purge from Cloudflare.",
+                'log_level': 'error',
+                'cloudflare_request_data': '{}',
+                'cloudflare_request_errors': 'Cloudflare doesn\'t like you 😡',
+            },
         )
 
-    def test_log__http_error(self, logger_mock, delete_mock):
+    def test_log__http_error(self, delete_mock):
         # Mock an HTTP error response
         response_500 = Mock()
         response_500.status_code = 500
@@ -101,24 +113,35 @@ def test_log__http_error(self, logger_mock, delete_mock):
             response=response_500
         )
 
-        purge_all_from_cache()
-        logger_mock.error.assert_called_once_with(
-            'Couldn\'t purge from Cloudflare with data: %s. HTTPError: %d %s',
-            '{}',
-            500,
-            'something happened'
+        with capture_logs_with_contextvars() as cap_logs:
+            purge_all_from_cache()
+        log_entry = cap_logs[0]
+        self.assertEqual(
+            log_entry,
+            {
+                'event': "Couldn't purge from Cloudflare.",
+                'log_level': 'error',
+                'exc_info': True,
+                'cloudflare_request_data': '{}',
+            },
         )
 
-    def test_log__invalid_url(self, logger_mock, delete_mock):
+    def test_log__invalid_url(self, delete_mock):
         # Mock a URL error response
         delete_mock.return_value.json.side_effect = ValueError
         delete_mock.return_value.raise_for_status.side_effect = InvalidURL(
             'something happened',
         )
 
-        purge_all_from_cache()
-        logger_mock.error.assert_called_once_with(
-            'Couldn\'t purge from Cloudflare with data: %s. InvalidURL: %s',
-            '{}',
-            'something happened'
+        with capture_logs_with_contextvars() as cap_logs:
+            purge_all_from_cache()
+        log_entry = cap_logs[0]
+        self.assertEqual(
+            log_entry,
+            {
+                'event': "Couldn't purge from Cloudflare.",
+                'log_level': 'error',
+                'exc_info': True,
+                'cloudflare_request_data': '{}',
+            },
         )

cloudflare/utils.py

@@ -27,7 +27,9 @@ def _purge(backend: CloudflareBackend, data={}) -> None:
     "Send a delete request to the Cloudflare API"
     purge_url = 'https://api.cloudflare.com/client/v4/zones/{0}/purge_cache'.format(backend.cloudflare_zoneid)
     string_data = json.dumps(data)
-
+    structlog.contextvars.bind_contextvars(
+        cloudflare_request_data=string_data,
+    )
     response = requests.delete(
         purge_url,
         json=data,
@@ -44,24 +46,28 @@ def _purge(backend: CloudflareBackend, data={}) -> None:
             response_json = response.json()
         except ValueError:
             if response.status_code != 200:
+
                 response.raise_for_status()
             else:
-                logger.error("Couldn't purge from Cloudflare with data: %s. Unexpected JSON parse error.", string_data)
+                logger.exception("Couldn't purge from Cloudflare. Unexpected JSON parse error.")
 
-    except requests.exceptions.HTTPError as e:
-        logger.error("Couldn't purge from Cloudflare with data: %s. HTTPError: %d %s", string_data, e.response.status_code, str(e))
+    except requests.exceptions.HTTPError:
+        logger.exception("Couldn't purge from Cloudflare.")
         return
 
-    except requests.exceptions.InvalidURL as e:
-        logger.error("Couldn't purge from Cloudflare with data: %s. InvalidURL: %s", string_data, str(e))
+    except requests.exceptions.InvalidURL:
+        logger.exception("Couldn't purge from Cloudflare.")
         return
 
     if response_json['success'] is False:
         error_messages = ', '.join([str(err['message']) for err in response_json['errors']])
-        logger.error("Couldn't purge from Cloudflare with data: %s. Cloudflare errors '%s'", string_data, error_messages)
+        logger.error(
+            "Couldn't purge from Cloudflare.",
+            cloudflare_request_errors=error_messages,
+        )
         return
 
-    logger.info("Purged from CloudFlare with data: %s", string_data)
+    logger.info("Purged from CloudFlare")
 
 
 @_for_every_cloudflare_backend

common/tests/test_middleware.py

@@ -1,27 +1,12 @@
-import contextlib
 from unittest import mock
 
-import structlog
 from django.test import TestCase, RequestFactory
 from django.contrib.auth import get_user_model
 from wagtail.models import Page
 
 from common.middleware import RequestLogMiddleware
 
-
-@contextlib.contextmanager
-def capture_logs_with_contextvars():
-    """Modified version of structlog.testing.capture_logs that captures
-    data bound to structlog's loggers with ``bind_contextvars``.
-
-    """
-    cap = structlog.testing.LogCapture()
-    old_processors = structlog.get_config()['processors']
-    try:
-        structlog.configure(processors=[structlog.contextvars.merge_contextvars, cap])
-        yield cap.entries
-    finally:
-        structlog.configure(processors=old_processors)
+from .utils import capture_logs_with_contextvars
 
 
 class RequestLogTestCase(TestCase):

common/tests/utils.py

@@ -1,3 +1,6 @@
+import contextlib
+
+import structlog
 from wagtail.models import Site
 
 from directory.models import DirectorySettings
@@ -8,3 +11,18 @@ def turn_on_instance_scanning():
     settings = DirectorySettings.for_site(site)
     settings.show_scan_results = True
     settings.save()
+
+
+@contextlib.contextmanager
+def capture_logs_with_contextvars():
+    """Modified version of structlog.testing.capture_logs that captures
+    data bound to structlog's loggers with ``bind_contextvars``.
+
+    """
+    cap = structlog.testing.LogCapture()
+    old_processors = structlog.get_config()['processors']
+    try:
+        structlog.configure(processors=[structlog.contextvars.merge_contextvars, cap])
+        yield cap.entries
+    finally:
+        structlog.configure(processors=old_processors)