From a1d620cea4c86add878fd9e8b52aa066b8bcfccd Mon Sep 17 00:00:00 2001 From: Cameron Higby-Naquin Date: Thu, 14 Dec 2023 16:27:14 -0500 Subject: [PATCH] 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 | 75 ++++++++++++++++-------- cloudflare/utils.py | 22 ++++--- common/tests/test_middleware.py | 17 +----- common/tests/utils.py | 18 ++++++ 4 files changed, 82 insertions(+), 50 deletions(-) diff --git a/cloudflare/tests/test_cache_tag_purge.py b/cloudflare/tests/test_cache_tag_purge.py index 044c0c3b..a7178577 100644 --- a/cloudflare/tests/test_cache_tag_purge.py +++ b/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': '{}', + }, ) diff --git a/cloudflare/utils.py b/cloudflare/utils.py index a91435e6..67837b4e 100644 --- a/cloudflare/utils.py +++ b/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 diff --git a/common/tests/test_middleware.py b/common/tests/test_middleware.py index c508b8a3..370e2a52 100644 --- a/common/tests/test_middleware.py +++ b/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): diff --git a/common/tests/utils.py b/common/tests/utils.py index 276292e6..46551e29 100644 --- a/common/tests/utils.py +++ b/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)