From 6ed8a4ca3cff4e06ce95f876bf2eeb4cbd6a4a7d Mon Sep 17 00:00:00 2001 From: Paul Schilling Date: Tue, 9 May 2023 09:18:38 +0200 Subject: [PATCH 1/9] add logging of request + response body --- log_outgoing_requests/admin.py | 24 +++++- log_outgoing_requests/formatters.py | 13 ++- log_outgoing_requests/handlers.py | 80 ++++++++++++------- log_outgoing_requests/log_requests.py | 8 +- ...0002_outgoingrequestslogconfig_and_more.py | 77 ++++++++++++++++++ log_outgoing_requests/models.py | 51 ++++++++++++ .../log_outgoing_requests/css/admin.css | 6 ++ testapp/settings.py | 2 + 8 files changed, 225 insertions(+), 36 deletions(-) create mode 100644 log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py create mode 100644 log_outgoing_requests/static/log_outgoing_requests/css/admin.css diff --git a/log_outgoing_requests/admin.py b/log_outgoing_requests/admin.py index fdc9531..86709f2 100644 --- a/log_outgoing_requests/admin.py +++ b/log_outgoing_requests/admin.py @@ -1,7 +1,14 @@ from django.contrib import admin from django.utils.translation import gettext as _ -from .models import OutgoingRequestsLog +from solo.admin import SingletonModelAdmin + +from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig + + +@admin.display(description="Response body") +def response_body(obj): + return f"{obj}".upper() @admin.register(OutgoingRequestsLog) @@ -19,6 +26,8 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin): "res_content_type", "req_headers", "res_headers", + "req_body", + "res_body", "trace", ) readonly_fields = fields @@ -31,7 +40,7 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin): "response_ms", "timestamp", ) - list_filter = ("method", "status_code", "hostname") + list_filter = ("method", "status_code", "hostname", "timestamp") search_fields = ("url", "params", "hostname") date_hierarchy = "timestamp" show_full_result_count = False @@ -46,3 +55,14 @@ def query_params(self, obj): return obj.query_params query_params.short_description = _("Query parameters") + + class Media: + css = { + "all": ("log_outgoing_requests/css/admin.css",), + } + + +@admin.register(OutgoingRequestsLogConfig) +class OutgoingRequestsLogConfigAdmin(SingletonModelAdmin): + fields = ("save_to_db", "save_body",) + list_display = ("save_to_db", "save_body",) diff --git a/log_outgoing_requests/formatters.py b/log_outgoing_requests/formatters.py index 8144286..b6905c8 100644 --- a/log_outgoing_requests/formatters.py +++ b/log_outgoing_requests/formatters.py @@ -1,11 +1,18 @@ import logging import textwrap +from django.conf import settings + class HttpFormatter(logging.Formatter): def _formatHeaders(self, d): return "\n".join(f"{k}: {v}" for k, v in d.items()) + def _formatBody(self, content: dict, request_or_response: str) -> str: + if settings.LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT: + return f"\n{request_or_response} body:\n{content}" + return "" + def formatMessage(self, record): result = super().formatMessage(record) if record.name == "requests": @@ -13,11 +20,11 @@ def formatMessage(self, record): """ ---------------- request ---------------- {req.method} {req.url} - {reqhdrs} + {reqhdrs} {request_body} ---------------- response ---------------- {res.status_code} {res.reason} {res.url} - {reshdrs} + {reshdrs} {response_body} """ ).format( @@ -25,6 +32,8 @@ def formatMessage(self, record): res=record.res, reqhdrs=self._formatHeaders(record.req.headers), reshdrs=self._formatHeaders(record.res.headers), + request_body=self._formatBody(record.req.body, "Request"), + response_body=self._formatBody(record.res.json(), "Response"), ) return result diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index 631f147..d67db22 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -5,40 +5,64 @@ from django.conf import settings +ALLOWED_CONTENT_TYPES = [ + "application/json", "multipart/form-data", "text/html", "text/plain", +] + + class DatabaseOutgoingRequestsHandler(logging.Handler): def emit(self, record): - if settings.LOG_OUTGOING_REQUESTS_DB_SAVE: + from .models import OutgoingRequestsLogConfig + config = OutgoingRequestsLogConfig.get_solo() + + if config.save_to_db or settings.LOG_OUTGOING_REQUESTS_DB_SAVE: from .models import OutgoingRequestsLog trace = None - # save only the requests coming from the library requests - if record and record.getMessage() == "Outgoing request": - safe_req_headers = record.req.headers.copy() - - if "Authorization" in safe_req_headers: - safe_req_headers["Authorization"] = "***hidden***" - - if record.exc_info: - trace = traceback.format_exc() - - parsed_url = urlparse(record.req.url) - kwargs = { - "url": record.req.url, - "hostname": parsed_url.hostname, - "params": parsed_url.params, - "status_code": record.res.status_code, - "method": record.req.method, - "req_content_type": record.req.headers.get("Content-Type", ""), - "res_content_type": record.res.headers.get("Content-Type", ""), - "timestamp": record.requested_at, - "response_ms": int(record.res.elapsed.total_seconds() * 1000), - "req_headers": self.format_headers(safe_req_headers), - "res_headers": self.format_headers(record.res.headers), - "trace": trace, - } - - OutgoingRequestsLog.objects.create(**kwargs) + # skip requests not coming from the library requests + if not record or not record.getMessage() == "Outgoing request": + return + + # skip requests with non-allowed content + request_content_type = record.req.headers.get("Content-Type", "") + response_content_type = record.res.headers.get("Content-Type", "") + + if not ( + request_content_type in ALLOWED_CONTENT_TYPES and + response_content_type in ALLOWED_CONTENT_TYPES + ): + return + + safe_req_headers = record.req.headers.copy() + + if "Authorization" in safe_req_headers: + safe_req_headers["Authorization"] = "***hidden***" + + if record.exc_info: + trace = traceback.format_exc() + + parsed_url = urlparse(record.req.url) + kwargs = { + "url": record.req.url, + "hostname": parsed_url.hostname, + "params": parsed_url.params, + "status_code": record.res.status_code, + "method": record.req.method, + "req_content_type": record.req.headers.get("Content-Type", ""), + "res_content_type": record.res.headers.get("Content-Type", ""), + "timestamp": record.requested_at, + "response_ms": int(record.res.elapsed.total_seconds() * 1000), + "req_headers": self.format_headers(safe_req_headers), + "res_headers": self.format_headers(record.res.headers), + "trace": trace, + } + + if config.save_body or settings.LOG_OUTGOING_REQUESTS_SAVE_BODY: + kwargs["req_body"] = record.req.body, + kwargs["res_body"] = record.res.json(), + + OutgoingRequestsLog.objects.create(**kwargs) def format_headers(self, headers): return "\n".join(f"{k}: {v}" for k, v in headers.items()) diff --git a/log_outgoing_requests/log_requests.py b/log_outgoing_requests/log_requests.py index e32a513..5939866 100644 --- a/log_outgoing_requests/log_requests.py +++ b/log_outgoing_requests/log_requests.py @@ -20,16 +20,16 @@ def install_outgoing_requests_logging(): Log all outgoing requests which are made by the library requests during a session. """ - if hasattr(Session, "_original_request"): + if hasattr(Session, "_initial_request"): logger.debug( - "Session is already patched OR has an ``_original_request`` attribute." + "Session is already patched OR has an ``_initial_request`` attribute." ) return - Session._original_request = Session.request + Session._initial_request = Session.request def new_request(self, *args, **kwargs): self.hooks["response"].append(hook_requests_logging) - return self._original_request(*args, **kwargs) + return self._initial_request(*args, **kwargs) Session.request = new_request diff --git a/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py b/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py new file mode 100644 index 0000000..3274041 --- /dev/null +++ b/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py @@ -0,0 +1,77 @@ +# Generated by Django 4.2.1 on 2023-05-09 07:48 + +from django.db import migrations, models + + +class Migration(migrations.Migration): + dependencies = [ + ("log_outgoing_requests", "0001_initial"), + ] + + operations = [ + migrations.CreateModel( + name="OutgoingRequestsLogConfig", + fields=[ + ( + "id", + models.AutoField( + auto_created=True, + primary_key=True, + serialize=False, + verbose_name="ID", + ), + ), + ( + "save_to_db", + models.IntegerField( + blank=True, + choices=[(None, "Use default"), (0, "No"), (1, "Yes")], + help_text="Whether request logs should be saved to the database (default: True)", + null=True, + verbose_name="Save logs to database", + ), + ), + ( + "save_body", + models.IntegerField( + blank=True, + choices=[(None, "Use default"), (0, "No"), (1, "Yes")], + help_text="Wheter the body of the request and response should be logged (default: False). This option is ignored if 'Save Logs to database' is set to False.", + null=True, + verbose_name="Save request + response body", + ), + ), + ], + options={ + "verbose_name": "Outgoing Requests Logs Configuration", + }, + ), + migrations.AlterModelOptions( + name="outgoingrequestslog", + options={ + "permissions": [("can_view_logs", "Can view outgoing request logs")], + "verbose_name": "Outgoing Requests Log", + "verbose_name_plural": "Outgoing Requests Logs", + }, + ), + migrations.AddField( + model_name="outgoingrequestslog", + name="req_body", + field=models.TextField( + blank=True, + help_text="The request body.", + null=True, + verbose_name="Request body", + ), + ), + migrations.AddField( + model_name="outgoingrequestslog", + name="res_body", + field=models.JSONField( + blank=True, + help_text="The response body.", + null=True, + verbose_name="Response body", + ), + ), + ] diff --git a/log_outgoing_requests/models.py b/log_outgoing_requests/models.py index 215e481..b6bccb7 100644 --- a/log_outgoing_requests/models.py +++ b/log_outgoing_requests/models.py @@ -4,6 +4,10 @@ from django.utils.functional import cached_property from django.utils.translation import gettext_lazy as _ +from solo.models import SingletonModel + +from django.conf import settings + class OutgoingRequestsLog(models.Model): url = models.URLField( @@ -60,12 +64,24 @@ class OutgoingRequestsLog(models.Model): null=True, help_text=_("The request headers."), ) + req_body = models.TextField( + verbose_name=_("Request body"), + blank=True, + null=True, + help_text=_("The request body.") + ) res_headers = models.TextField( verbose_name=_("Response headers"), blank=True, null=True, help_text=_("The response headers."), ) + res_body = models.JSONField( + verbose_name=_("Response body"), + blank=True, + null=True, + help_text=_("The response body.") + ) response_ms = models.PositiveIntegerField( verbose_name=_("Response in ms"), default=0, @@ -86,6 +102,9 @@ class OutgoingRequestsLog(models.Model): class Meta: verbose_name = _("Outgoing Requests Log") verbose_name_plural = _("Outgoing Requests Logs") + permissions = [ + ("can_view_logs", "Can view outgoing request logs"), + ] def __str__(self): return ("{hostname} at {date}").format( @@ -99,3 +118,35 @@ def url_parsed(self): @property def query_params(self): return self.url_parsed.query + + +class OutgoingRequestsLogConfig(SingletonModel): + class SaveLogsChoices(models.IntegerChoices): + NO = 0, _("No") + YES = 1, _("Yes") + + __empty__ = _("Use default") + + save_to_db = models.IntegerField( + _("Save logs to database"), + choices=SaveLogsChoices.choices, + blank=True, + null=True, + help_text=_( + "Whether request logs should be saved to the database (default: {default})" + ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE), + ) + save_body = models.IntegerField( + _("Save request + response body"), + choices=SaveLogsChoices.choices, + blank=True, + null=True, + help_text=_( + "Wheter the body of the request and response should be logged (default: " + "{default}). This option is ignored if 'Save Logs to database' is set to " + "False." + ).format(default=settings.LOG_OUTGOING_REQUESTS_SAVE_BODY), + ) + + class Meta: + verbose_name = _("Outgoing Requests Logs Configuration") diff --git a/log_outgoing_requests/static/log_outgoing_requests/css/admin.css b/log_outgoing_requests/static/log_outgoing_requests/css/admin.css new file mode 100644 index 0000000..8485b3b --- /dev/null +++ b/log_outgoing_requests/static/log_outgoing_requests/css/admin.css @@ -0,0 +1,6 @@ +.field-res_body { + display: inline-block; + width: 40rem; + font-family: monospace; + line-height: 1.5rem; +} diff --git a/testapp/settings.py b/testapp/settings.py index 15ab347..9a91f5e 100644 --- a/testapp/settings.py +++ b/testapp/settings.py @@ -16,6 +16,7 @@ INSTALLED_APPS = [ "django.contrib.contenttypes", "django.contrib.auth", + "django.contrib.messages", "django.contrib.sessions", "django.contrib.admin", "log_outgoing_requests", @@ -91,6 +92,7 @@ # LOG OUTGOING REQUESTS # LOG_OUTGOING_REQUESTS_DB_SAVE = True +LOG_OUTGOING_REQUESTS_SAVE_BODY = False ROOT_URLCONF = "testapp.urls" From 68e8020d820dfe032f3dffc1a294b9b9a2b1e261 Mon Sep 17 00:00:00 2001 From: Paul Schilling Date: Tue, 9 May 2023 11:27:16 +0200 Subject: [PATCH 2/9] add tests for logging request + response body --- log_outgoing_requests/handlers.py | 2 +- tests/test_logging.py | 198 +++++++++++++++++++++++++++++- 2 files changed, 198 insertions(+), 2 deletions(-) diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index d67db22..a6806ea 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -6,7 +6,7 @@ ALLOWED_CONTENT_TYPES = [ - "application/json", "multipart/form-data", "text/html", "text/plain", + "application/json", "multipart/form-data", "text/html", "text/plain", "", None, ] diff --git a/tests/test_logging.py b/tests/test_logging.py index e0f8dd2..fc6bc6c 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -4,7 +4,7 @@ import requests_mock from freezegun import freeze_time -from log_outgoing_requests.models import OutgoingRequestsLog +from log_outgoing_requests.models import OutgoingRequestsLog, OutgoingRequestsLogConfig @requests_mock.Mocker() @@ -30,6 +30,7 @@ def test_outgoing_requests_are_logged(self, m): self.assertEqual(logs.records[0].levelname, "DEBUG") @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) def test_expected_data_is_saved_when_saving_enabled(self, m): methods = [ ("GET", requests.get, m.get), @@ -93,6 +94,7 @@ def test_expected_data_is_saved_when_saving_enabled(self, m): request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S"), "2021-10-18 13:00:00", ) + self.assertEqual(request_log.res_body[0], {"test": "data"}) self.assertIsNone(request_log.trace) @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) @@ -139,3 +141,197 @@ def test_request_data_is_not_saved_when_saving_disabled(self, m): requests.get("http://example.com/some-path?version=2.0") self.assertFalse(OutgoingRequestsLog.objects.exists()) + + @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) + def test_logging_disallowed_content_type_request(self, m): + methods = [ + ("GET", requests.get, m.get), + ("POST", requests.post, m.post), + ("PUT", requests.put, m.put), + ("PATCH", requests.patch, m.patch), + ("DELETE", requests.delete, m.delete), + ("HEAD", requests.head, m.head), + ] + + for method, func, mocked in methods: + with self.subTest(): + mocked( + "http://example.com/some-path?version=2.0", + status_code=200, + json={"test": "data"}, + request_headers={ + "Authorization": "test", + "Content-Type": "video/mp4", + }, + headers={ + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "text/html", + }, + ) + + func( + "http://example.com/some-path?version=2.0", + headers={"Authorization": "test", "Content-Type": "video/mp4"}, + ) + + request_log = OutgoingRequestsLog.objects.last() + + self.assertIsNone(request_log) + + @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) + def test_logging_disallowed_content_type_response(self, m): + methods = [ + ("GET", requests.get, m.get), + ("POST", requests.post, m.post), + ("PUT", requests.put, m.put), + ("PATCH", requests.patch, m.patch), + ("DELETE", requests.delete, m.delete), + ("HEAD", requests.head, m.head), + ] + + for method, func, mocked in methods: + with self.subTest(): + mocked( + "http://example.com/some-path?version=2.0", + status_code=200, + json={"test": "data"}, + request_headers={ + "Authorization": "test", + "Content-Type": "text/html", + }, + headers={ + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "video/mp4", + }, + ) + + func( + "http://example.com/some-path?version=2.0", + headers={"Authorization": "test", "Content-Type": "text/html"}, + ) + + request_log = OutgoingRequestsLog.objects.last() + + self.assertIsNone(request_log) + + @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) + def test_body_not_saved_when_setting_disabled(self, m): + methods = [ + ("GET", requests.get, m.get), + ("POST", requests.post, m.post), + ("PUT", requests.put, m.put), + ("PATCH", requests.patch, m.patch), + ("DELETE", requests.delete, m.delete), + ("HEAD", requests.head, m.head), + ] + + for method, func, mocked in methods: + with self.subTest(): + mocked( + "http://example.com/some-path?version=2.0", + status_code=200, + json={"test": "data"}, + request_headers={ + "Authorization": "test", + "Content-Type": "text/html", + }, + headers={ + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "application/json", + }, + ) + + func( + "http://example.com/some-path?version=2.0", + headers={"Authorization": "test", "Content-Type": "text/html"}, + ) + + request_log = OutgoingRequestsLog.objects.last() + + self.assertIsNone(request_log.res_body) + + @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) + def test_admin_override_db_save(self, m): + config = OutgoingRequestsLogConfig.get_solo() + config.save_to_db = 1 # True + config.save() + + methods = [ + ("GET", requests.get, m.get), + ("POST", requests.post, m.post), + ("PUT", requests.put, m.put), + ("PATCH", requests.patch, m.patch), + ("DELETE", requests.delete, m.delete), + ("HEAD", requests.head, m.head), + ] + + for method, func, mocked in methods: + with self.subTest(): + mocked( + "http://example.com/some-path?version=2.0", + status_code=200, + json={"test": "data"}, + request_headers={ + "Authorization": "test", + "Content-Type": "text/html", + }, + headers={ + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "application/json", + }, + ) + + func( + "http://example.com/some-path?version=2.0", + headers={"Authorization": "test", "Content-Type": "text/html"}, + ) + + request_log = OutgoingRequestsLog.objects.last() + + self.assertIsNotNone(request_log) + self.assertIsNone(request_log.res_body) + + @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) + @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) + def test_admin_override_save_body(self, m): + config = OutgoingRequestsLogConfig.get_solo() + config.save_body = 1 # True + config.save() + + methods = [ + ("GET", requests.get, m.get), + ("POST", requests.post, m.post), + ("PUT", requests.put, m.put), + ("PATCH", requests.patch, m.patch), + ("DELETE", requests.delete, m.delete), + ("HEAD", requests.head, m.head), + ] + + for method, func, mocked in methods: + with self.subTest(): + mocked( + "http://example.com/some-path?version=2.0", + status_code=200, + json={"test": "data"}, + request_headers={ + "Authorization": "test", + "Content-Type": "text/html", + }, + headers={ + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "application/json", + }, + ) + + func( + "http://example.com/some-path?version=2.0", + headers={"Authorization": "test", "Content-Type": "text/html"}, + ) + + request_log = OutgoingRequestsLog.objects.last() + + self.assertIsNotNone(request_log.res_body) From 5008ad835592962de9393b82e0ecbb3061b1a201 Mon Sep 17 00:00:00 2001 From: Paul Schilling Date: Tue, 9 May 2023 13:01:50 +0200 Subject: [PATCH 3/9] update README and docs --- README.rst | 5 ++++- docs/quickstart.rst | 3 +++ log_outgoing_requests/admin.py | 10 ++++++++-- log_outgoing_requests/handlers.py | 17 +++++++++++------ log_outgoing_requests/models.py | 7 +++---- setup.cfg | 1 + 6 files changed, 30 insertions(+), 13 deletions(-) diff --git a/README.rst b/README.rst index 2ad5883..4dfca82 100644 --- a/README.rst +++ b/README.rst @@ -97,6 +97,9 @@ To use this with your project you need to follow these steps: } LOG_OUTGOING_REQUESTS_DB_SAVE = True # save logs enabled/disabled based on the boolean value + LOG_OUTGOING_REQUESTS_SAVE_BODY = True # save request/response body + LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True # log request/response body to STDOUT + #. Run the migrations @@ -113,7 +116,7 @@ To use this with your project you need to follow these steps: print(res.json()) #. Check stdout for the printable output, and navigate to ``/admin/log_outgoing_requests/outgoingrequestslog/`` to see - the saved log records + the saved log records. The settings for saving logs can by overridden under ``/admin/log_outgoing_requests/outgoingrequestslogconfig/``. Local development diff --git a/docs/quickstart.rst b/docs/quickstart.rst index d1fabcb..70e3301 100644 --- a/docs/quickstart.rst +++ b/docs/quickstart.rst @@ -58,6 +58,9 @@ Installation } LOG_OUTGOING_REQUESTS_DB_SAVE = True # save logs enabled/disabled based on the boolean value + LOG_OUTGOING_REQUESTS_SAVE_BODY = True # save request/response body + LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True # log request/response body to STDOUT + #. Run ``python manage.py migrate`` to create the necessary database tables. diff --git a/log_outgoing_requests/admin.py b/log_outgoing_requests/admin.py index 86709f2..a05ce64 100644 --- a/log_outgoing_requests/admin.py +++ b/log_outgoing_requests/admin.py @@ -64,5 +64,11 @@ class Media: @admin.register(OutgoingRequestsLogConfig) class OutgoingRequestsLogConfigAdmin(SingletonModelAdmin): - fields = ("save_to_db", "save_body",) - list_display = ("save_to_db", "save_body",) + fields = ( + "save_to_db", + "save_body", + ) + list_display = ( + "save_to_db", + "save_body", + ) diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index a6806ea..1435083 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -4,15 +4,20 @@ from django.conf import settings - ALLOWED_CONTENT_TYPES = [ - "application/json", "multipart/form-data", "text/html", "text/plain", "", None, + "application/json", + "multipart/form-data", + "text/html", + "text/plain", + "", + None, ] class DatabaseOutgoingRequestsHandler(logging.Handler): def emit(self, record): from .models import OutgoingRequestsLogConfig + config = OutgoingRequestsLogConfig.get_solo() if config.save_to_db or settings.LOG_OUTGOING_REQUESTS_DB_SAVE: @@ -29,8 +34,8 @@ def emit(self, record): response_content_type = record.res.headers.get("Content-Type", "") if not ( - request_content_type in ALLOWED_CONTENT_TYPES and - response_content_type in ALLOWED_CONTENT_TYPES + request_content_type in ALLOWED_CONTENT_TYPES + and response_content_type in ALLOWED_CONTENT_TYPES ): return @@ -59,8 +64,8 @@ def emit(self, record): } if config.save_body or settings.LOG_OUTGOING_REQUESTS_SAVE_BODY: - kwargs["req_body"] = record.req.body, - kwargs["res_body"] = record.res.json(), + kwargs["req_body"] = (record.req.body,) + kwargs["res_body"] = (record.res.json(),) OutgoingRequestsLog.objects.create(**kwargs) diff --git a/log_outgoing_requests/models.py b/log_outgoing_requests/models.py index b6bccb7..9de596e 100644 --- a/log_outgoing_requests/models.py +++ b/log_outgoing_requests/models.py @@ -1,13 +1,12 @@ from urllib.parse import urlparse +from django.conf import settings from django.db import models from django.utils.functional import cached_property from django.utils.translation import gettext_lazy as _ from solo.models import SingletonModel -from django.conf import settings - class OutgoingRequestsLog(models.Model): url = models.URLField( @@ -68,7 +67,7 @@ class OutgoingRequestsLog(models.Model): verbose_name=_("Request body"), blank=True, null=True, - help_text=_("The request body.") + help_text=_("The request body."), ) res_headers = models.TextField( verbose_name=_("Response headers"), @@ -80,7 +79,7 @@ class OutgoingRequestsLog(models.Model): verbose_name=_("Response body"), blank=True, null=True, - help_text=_("The response body.") + help_text=_("The response body."), ) response_ms = models.PositiveIntegerField( verbose_name=_("Response in ms"), diff --git a/setup.cfg b/setup.cfg index 7fe5f25..5eb1286 100644 --- a/setup.cfg +++ b/setup.cfg @@ -37,6 +37,7 @@ packages = find: install_requires = django >= 3.2 requests + django-solo tests_require = pytest pytest-django From 6bae3ef39ac9ec480a1c8db53128e0cc6a443f4b Mon Sep 17 00:00:00 2001 From: Paul Schilling Date: Thu, 11 May 2023 14:00:58 +0200 Subject: [PATCH 4/9] process PR feedback --- .github/workflows/ci.yml | 5 +- README.rst | 17 +- docs/quickstart.rst | 12 +- log_outgoing_requests/admin.py | 53 +- log_outgoing_requests/constants.py | 8 + log_outgoing_requests/datastructures.py | 18 + log_outgoing_requests/formatters.py | 41 +- log_outgoing_requests/handlers.py | 71 +-- ...0002_outgoingrequestslogconfig_and_more.py | 158 ++++- log_outgoing_requests/models.py | 146 +++-- .../log_outgoing_requests/css/admin.css | 11 +- .../log_outgoing_requests/change_form.html | 16 + log_outgoing_requests/utils.py | 150 +++++ setup.cfg | 6 +- testapp/settings.py | 12 +- tests/conftest.py | 59 ++ tests/test_admin.py | 97 +++ tests/test_formatter.py | 46 ++ tests/test_logging.py | 559 ++++++++---------- tests/test_utils.py | 167 ++++++ tox.ini | 9 +- 21 files changed, 1169 insertions(+), 492 deletions(-) create mode 100644 log_outgoing_requests/constants.py create mode 100644 log_outgoing_requests/datastructures.py create mode 100644 log_outgoing_requests/templates/log_outgoing_requests/change_form.html create mode 100644 log_outgoing_requests/utils.py create mode 100644 tests/conftest.py create mode 100644 tests/test_admin.py create mode 100644 tests/test_formatter.py create mode 100644 tests/test_utils.py diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 4e1c27c..92204c8 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -15,11 +15,8 @@ jobs: runs-on: ubuntu-latest strategy: matrix: - python: ["3.7", "3.8", "3.9", "3.10"] + python: ["3.8", "3.9", "3.10"] django: ["3.2", "4.1"] - exclude: - - python: "3.7" - django: "4.1" name: Run the test suite (Python ${{ matrix.python }}, Django ${{ matrix.django }}) diff --git a/README.rst b/README.rst index 4dfca82..f8b9f5c 100644 --- a/README.rst +++ b/README.rst @@ -97,8 +97,16 @@ To use this with your project you need to follow these steps: } LOG_OUTGOING_REQUESTS_DB_SAVE = True # save logs enabled/disabled based on the boolean value - LOG_OUTGOING_REQUESTS_SAVE_BODY = True # save request/response body - LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True # log request/response body to STDOUT + LOG_OUTGOING_REQUESTS_DB_SAVE_BODY = True # save request/response body + LOG_OUTGOING_REQUESTS_EMIT_BODY = True # log request/response body + LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + "text/*", + "application/json", + "application/xml", + "application/soap+xml", + ] # save request/response bodies with matching content type + LOG_OUTGOING_REQUESTS_MAX_CONTENT_LENGTH = 524_288 # maximal size (in bytes) for the request/response body + LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True #. Run the migrations @@ -115,8 +123,9 @@ To use this with your project you need to follow these steps: res = requests.get("https://httpbin.org/json") print(res.json()) -#. Check stdout for the printable output, and navigate to ``/admin/log_outgoing_requests/outgoingrequestslog/`` to see - the saved log records. The settings for saving logs can by overridden under ``/admin/log_outgoing_requests/outgoingrequestslogconfig/``. +#. Check stdout for the printable output, and navigate to ``Admin > Miscellaneous > Outgoing Requests Logs`` + to see the saved log records. In order to override the settings for saving logs, navigate to + ``Admin > Miscellaneous > Outgoing Requests Log Configuration``. Local development diff --git a/docs/quickstart.rst b/docs/quickstart.rst index 70e3301..24c7b9e 100644 --- a/docs/quickstart.rst +++ b/docs/quickstart.rst @@ -58,8 +58,16 @@ Installation } LOG_OUTGOING_REQUESTS_DB_SAVE = True # save logs enabled/disabled based on the boolean value - LOG_OUTGOING_REQUESTS_SAVE_BODY = True # save request/response body - LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True # log request/response body to STDOUT + LOG_OUTGOING_REQUESTS_DB_SAVE_BODY = True # save request/response body + LOG_OUTGOING_REQUESTS_EMIT_BODY = True # log request/response body + LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + "text/*", + "application/json", + "application/xml", + "application/soap+xml", + ] # save request/response bodies with matching content type + LOG_OUTGOING_REQUESTS_MAX_CONTENT_LENGTH = 524_288 # maximal size (in bytes) for the request/response body + LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT = True #. Run ``python manage.py migrate`` to create the necessary database tables. diff --git a/log_outgoing_requests/admin.py b/log_outgoing_requests/admin.py index a05ce64..353692f 100644 --- a/log_outgoing_requests/admin.py +++ b/log_outgoing_requests/admin.py @@ -1,16 +1,14 @@ +from django import forms +from django.conf import settings from django.contrib import admin +from django.shortcuts import get_object_or_404 from django.utils.translation import gettext as _ -from solo.admin import SingletonModelAdmin +from solo.admin import SingletonModelAdmin # type: ignore from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig -@admin.display(description="Response body") -def response_body(obj): - return f"{obj}".upper() - - @admin.register(OutgoingRequestsLog) class OutgoingRequestsLogAdmin(admin.ModelAdmin): fields = ( @@ -26,8 +24,6 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin): "res_content_type", "req_headers", "res_headers", - "req_body", - "res_body", "trace", ) readonly_fields = fields @@ -40,10 +36,11 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin): "response_ms", "timestamp", ) - list_filter = ("method", "status_code", "hostname", "timestamp") + list_filter = ("method", "timestamp", "status_code", "hostname") search_fields = ("url", "params", "hostname") date_hierarchy = "timestamp" show_full_result_count = False + change_form_template = "log_outgoing_requests/change_form.html" def has_add_permission(self, request): return False @@ -54,7 +51,18 @@ def has_change_permission(self, request, obj=None): def query_params(self, obj): return obj.query_params - query_params.short_description = _("Query parameters") + def change_view(self, request, object_id, extra_context=None): + """ + Add log object to to context for use in template. + """ + log = get_object_or_404(OutgoingRequestsLog, id=object_id) + + extra_context = extra_context or {} + extra_context["log"] = log + + return super().change_view(request, object_id, extra_context=extra_context) + + query_params.short_description = _("Query parameters") # type: ignore class Media: css = { @@ -62,13 +70,22 @@ class Media: } +class ConfigAdminForm(forms.ModelForm): + class Meta: + model = OutgoingRequestsLogConfig + fields = "__all__" + widgets = {"allowed_content_types": forms.CheckboxSelectMultiple} + help_texts = { + "save_to_db": _( + "Whether request logs should be saved to the database (default: {default})." + ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE), + "save_body": _( + "Wheter the body of the request and response should be logged (default: " + "{default})." + ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE_BODY), + } + + @admin.register(OutgoingRequestsLogConfig) class OutgoingRequestsLogConfigAdmin(SingletonModelAdmin): - fields = ( - "save_to_db", - "save_body", - ) - list_display = ( - "save_to_db", - "save_body", - ) + form = ConfigAdminForm diff --git a/log_outgoing_requests/constants.py b/log_outgoing_requests/constants.py new file mode 100644 index 0000000..87522f0 --- /dev/null +++ b/log_outgoing_requests/constants.py @@ -0,0 +1,8 @@ +from django.db import models +from django.utils.translation import gettext_lazy as _ + + +class SaveLogsChoice(models.TextChoices): + use_default = "use_default", _("Use default") + yes = "yes", _("Yes") + no = "no", _("No") diff --git a/log_outgoing_requests/datastructures.py b/log_outgoing_requests/datastructures.py new file mode 100644 index 0000000..9ee6a36 --- /dev/null +++ b/log_outgoing_requests/datastructures.py @@ -0,0 +1,18 @@ +""" +Datastructure(s) for use in settings.py + +Note: do not place any Django-specific imports in this file, as +it must be imported in settings.py. +""" + +from dataclasses import dataclass + + +@dataclass +class ContentType: + """ + Data class for keeping track of content types and associated default encodings + """ + + pattern: str + default_encoding: str diff --git a/log_outgoing_requests/formatters.py b/log_outgoing_requests/formatters.py index b6905c8..047ad4a 100644 --- a/log_outgoing_requests/formatters.py +++ b/log_outgoing_requests/formatters.py @@ -8,32 +8,35 @@ class HttpFormatter(logging.Formatter): def _formatHeaders(self, d): return "\n".join(f"{k}: {v}" for k, v in d.items()) - def _formatBody(self, content: dict, request_or_response: str) -> str: - if settings.LOG_OUTGOING_REQUESTS_LOG_BODY_TO_STDOUT: + def _formatBody(self, content: str, request_or_response: str) -> str: + if settings.LOG_OUTGOING_REQUESTS_EMIT_BODY: return f"\n{request_or_response} body:\n{content}" return "" def formatMessage(self, record): result = super().formatMessage(record) - if record.name == "requests": - result += textwrap.dedent( - """ - ---------------- request ---------------- - {req.method} {req.url} - {reqhdrs} {request_body} - ---------------- response ---------------- - {res.status_code} {res.reason} {res.url} - {reshdrs} {response_body} + if record.name != "requests": + return result + result += textwrap.dedent( """ - ).format( - req=record.req, - res=record.res, - reqhdrs=self._formatHeaders(record.req.headers), - reshdrs=self._formatHeaders(record.res.headers), - request_body=self._formatBody(record.req.body, "Request"), - response_body=self._formatBody(record.res.json(), "Response"), - ) + ---------------- request ---------------- + {req.method} {req.url} + {reqhdrs} {request_body} + + ---------------- response ---------------- + {res.status_code} {res.reason} {res.url} + {reshdrs} {response_body} + + """ + ).format( + req=record.req, + res=record.res, + reqhdrs=self._formatHeaders(record.req.headers), + reshdrs=self._formatHeaders(record.res.headers), + request_body=self._formatBody(record.req.body, "Request"), + response_body=self._formatBody(record.res.content, "Response"), + ) return result diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index 1435083..55d378f 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -2,47 +2,31 @@ import traceback from urllib.parse import urlparse -from django.conf import settings - -ALLOWED_CONTENT_TYPES = [ - "application/json", - "multipart/form-data", - "text/html", - "text/plain", - "", - None, -] +from .utils import ( + check_content_length, + check_content_type, + get_default_encoding, + parse_content_type_header, +) class DatabaseOutgoingRequestsHandler(logging.Handler): def emit(self, record): - from .models import OutgoingRequestsLogConfig + from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig config = OutgoingRequestsLogConfig.get_solo() - if config.save_to_db or settings.LOG_OUTGOING_REQUESTS_DB_SAVE: - from .models import OutgoingRequestsLog - - trace = None + if config.save_logs_enabled: + trace = "" # skip requests not coming from the library requests if not record or not record.getMessage() == "Outgoing request": return - # skip requests with non-allowed content - request_content_type = record.req.headers.get("Content-Type", "") - response_content_type = record.res.headers.get("Content-Type", "") - - if not ( - request_content_type in ALLOWED_CONTENT_TYPES - and response_content_type in ALLOWED_CONTENT_TYPES - ): - return - - safe_req_headers = record.req.headers.copy() + scrubbed_req_headers = record.req.headers.copy() - if "Authorization" in safe_req_headers: - safe_req_headers["Authorization"] = "***hidden***" + if "Authorization" in scrubbed_req_headers: + scrubbed_req_headers["Authorization"] = "***hidden***" if record.exc_info: trace = traceback.format_exc() @@ -50,22 +34,39 @@ def emit(self, record): parsed_url = urlparse(record.req.url) kwargs = { "url": record.req.url, - "hostname": parsed_url.hostname, + "hostname": parsed_url.netloc, "params": parsed_url.params, "status_code": record.res.status_code, "method": record.req.method, - "req_content_type": record.req.headers.get("Content-Type", ""), - "res_content_type": record.res.headers.get("Content-Type", ""), "timestamp": record.requested_at, "response_ms": int(record.res.elapsed.total_seconds() * 1000), - "req_headers": self.format_headers(safe_req_headers), + "req_headers": self.format_headers(scrubbed_req_headers), "res_headers": self.format_headers(record.res.headers), "trace": trace, } - if config.save_body or settings.LOG_OUTGOING_REQUESTS_SAVE_BODY: - kwargs["req_body"] = (record.req.body,) - kwargs["res_body"] = (record.res.json(),) + if config.save_body_enabled: + # check request + content_type, encoding = parse_content_type_header(record.req) + if check_content_type(content_type) and check_content_length( + record.req, config + ): + kwargs["req_content_type"] = content_type + kwargs["req_body"] = record.req.body or b"" + kwargs["req_body_encoding"] = encoding or get_default_encoding( + content_type + ) + + # check response + content_type, encoding = parse_content_type_header(record.res) + if check_content_type(content_type) and check_content_length( + record.res, config + ): + kwargs["res_content_type"] = content_type + kwargs["res_body"] = record.res.content or b"" + kwargs[ + "res_body_encoding" + ] = record.res.encoding or get_default_encoding(content_type) OutgoingRequestsLog.objects.create(**kwargs) diff --git a/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py b/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py index 3274041..3c99adc 100644 --- a/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py +++ b/log_outgoing_requests/migrations/0002_outgoingrequestslogconfig_and_more.py @@ -1,7 +1,10 @@ -# Generated by Django 4.2.1 on 2023-05-09 07:48 +# Generated by Django 3.2.1 on 2023-06-02 16:22 +import django.core.validators from django.db import migrations, models +import log_outgoing_requests.models + class Migration(migrations.Migration): dependencies = [ @@ -23,55 +26,154 @@ class Migration(migrations.Migration): ), ( "save_to_db", - models.IntegerField( - blank=True, - choices=[(None, "Use default"), (0, "No"), (1, "Yes")], - help_text="Whether request logs should be saved to the database (default: True)", - null=True, + models.CharField( + choices=[ + ("use_default", "Use default"), + ("yes", "Yes"), + ("no", "No"), + ], + default="use_default", + max_length=11, verbose_name="Save logs to database", ), ), ( "save_body", - models.IntegerField( - blank=True, - choices=[(None, "Use default"), (0, "No"), (1, "Yes")], - help_text="Wheter the body of the request and response should be logged (default: False). This option is ignored if 'Save Logs to database' is set to False.", - null=True, + models.CharField( + choices=[ + ("use_default", "Use default"), + ("yes", "Yes"), + ("no", "No"), + ], + default="use_default", + max_length=11, verbose_name="Save request + response body", ), ), + ( + "max_content_length", + models.IntegerField( + default=log_outgoing_requests.models.get_default_max_content_length, + help_text="The maximal size of the request/response content (in bytes). If 'Require content length' is not checked, this setting has no effect.", + validators=[django.core.validators.MinValueValidator(0)], + verbose_name="Maximal content size", + ), + ), ], options={ - "verbose_name": "Outgoing Requests Logs Configuration", - }, - ), - migrations.AlterModelOptions( - name="outgoingrequestslog", - options={ - "permissions": [("can_view_logs", "Can view outgoing request logs")], - "verbose_name": "Outgoing Requests Log", - "verbose_name_plural": "Outgoing Requests Logs", + "verbose_name": "Outgoing Requests Log Configuration", }, ), migrations.AddField( model_name="outgoingrequestslog", name="req_body", - field=models.TextField( - blank=True, - help_text="The request body.", - null=True, - verbose_name="Request body", + field=models.BinaryField( + default=b"", help_text="The request body.", verbose_name="Request body" ), ), + migrations.AddField( + model_name="outgoingrequestslog", + name="req_body_encoding", + field=models.CharField(default="", max_length=24), + ), migrations.AddField( model_name="outgoingrequestslog", name="res_body", - field=models.JSONField( - blank=True, + field=models.BinaryField( + default=b"", help_text="The response body.", - null=True, verbose_name="Response body", ), ), + migrations.AddField( + model_name="outgoingrequestslog", + name="res_body_encoding", + field=models.CharField(default="", max_length=24), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="hostname", + field=models.CharField( + default="", + help_text="The netloc/hostname part of the url.", + max_length=255, + verbose_name="Hostname", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="method", + field=models.CharField( + blank=True, + help_text="The type of request method.", + max_length=10, + verbose_name="Method", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="req_content_type", + field=models.CharField( + default="", + help_text="The content type of the request.", + max_length=50, + verbose_name="Request content type", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="req_headers", + field=models.TextField( + default="", + help_text="The request headers.", + verbose_name="Request headers", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="res_content_type", + field=models.CharField( + default="", + help_text="The content type of the response.", + max_length=50, + verbose_name="Response content type", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="res_headers", + field=models.TextField( + default="", + help_text="The response headers.", + verbose_name="Response headers", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="response_ms", + field=models.PositiveIntegerField( + default=0, + help_text="This is the response time in ms.", + verbose_name="Response in ms", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="trace", + field=models.TextField( + default="", + help_text="Text providing information in case of request failure.", + verbose_name="Trace", + ), + ), + migrations.AlterField( + model_name="outgoingrequestslog", + name="url", + field=models.URLField( + default="", + help_text="The url of the outgoing request.", + max_length=1000, + verbose_name="URL", + ), + ), ] diff --git a/log_outgoing_requests/models.py b/log_outgoing_requests/models.py index 9de596e..89831cb 100644 --- a/log_outgoing_requests/models.py +++ b/log_outgoing_requests/models.py @@ -1,18 +1,23 @@ +import logging from urllib.parse import urlparse from django.conf import settings +from django.core.validators import MinValueValidator from django.db import models from django.utils.functional import cached_property from django.utils.translation import gettext_lazy as _ -from solo.models import SingletonModel +from solo.models import SingletonModel # type: ignore + +from .constants import SaveLogsChoice + +logger = logging.getLogger(__name__) class OutgoingRequestsLog(models.Model): url = models.URLField( verbose_name=_("URL"), max_length=1000, - blank=True, default="", help_text=_("The url of the outgoing request."), ) @@ -22,8 +27,7 @@ class OutgoingRequestsLog(models.Model): verbose_name=_("Hostname"), max_length=255, default="", - blank=True, - help_text=_("The hostname part of the url."), + help_text=_("The netloc/hostname part of the url."), ) params = models.TextField( verbose_name=_("Parameters"), @@ -39,7 +43,6 @@ class OutgoingRequestsLog(models.Model): method = models.CharField( verbose_name=_("Method"), max_length=10, - default="", blank=True, help_text=_("The type of request method."), ) @@ -47,44 +50,45 @@ class OutgoingRequestsLog(models.Model): verbose_name=_("Request content type"), max_length=50, default="", - blank=True, help_text=_("The content type of the request."), ) res_content_type = models.CharField( verbose_name=_("Response content type"), max_length=50, default="", - blank=True, help_text=_("The content type of the response."), ) req_headers = models.TextField( verbose_name=_("Request headers"), - blank=True, - null=True, + default="", help_text=_("The request headers."), ) - req_body = models.TextField( - verbose_name=_("Request body"), - blank=True, - null=True, - help_text=_("The request body."), - ) res_headers = models.TextField( verbose_name=_("Response headers"), - blank=True, - null=True, + default="", help_text=_("The response headers."), ) - res_body = models.JSONField( + req_body = models.BinaryField( + verbose_name=_("Request body"), + default=b"", + help_text=_("The request body."), + ) + res_body = models.BinaryField( verbose_name=_("Response body"), - blank=True, - null=True, + default=b"", help_text=_("The response body."), ) + req_body_encoding = models.CharField( + max_length=24, + default="", + ) + res_body_encoding = models.CharField( + max_length=24, + default="", + ) response_ms = models.PositiveIntegerField( verbose_name=_("Response in ms"), default=0, - blank=True, help_text=_("This is the response time in ms."), ) timestamp = models.DateTimeField( @@ -93,17 +97,13 @@ class OutgoingRequestsLog(models.Model): ) trace = models.TextField( verbose_name=_("Trace"), - blank=True, - null=True, + default="", help_text=_("Text providing information in case of request failure."), ) class Meta: verbose_name = _("Outgoing Requests Log") verbose_name_plural = _("Outgoing Requests Logs") - permissions = [ - ("can_view_logs", "Can view outgoing request logs"), - ] def __str__(self): return ("{hostname} at {date}").format( @@ -118,34 +118,86 @@ def url_parsed(self): def query_params(self): return self.url_parsed.query + @cached_property + def request_body_decoded(self) -> str: + """ + Decoded request body for use in template. + + If the stored encoding is not found (either because it is empty or because of + spelling errors etc.), we decode "blindly", replacing chars that could not be + decoded. + """ + try: + decoded = str(self.req_body, self.res_body_encoding, errors="replace") + except LookupError: + decoded = str(self.req_body, errors="replace") + return decoded + + @cached_property + def response_body_decoded(self) -> str: + """ + Decoded response body for use in template. + + If the stored encoding is not found (either because it is empty or because of + spelling errors etc.), we decode "blindly", replacing chars that could not be + decoded. + """ + try: + decoded = str(self.res_body, self.res_body_encoding, errors="replace") + except LookupError: + decoded = str(self.res_body, errors="replace") + return decoded -class OutgoingRequestsLogConfig(SingletonModel): - class SaveLogsChoices(models.IntegerChoices): - NO = 0, _("No") - YES = 1, _("Yes") - __empty__ = _("Use default") +def get_default_max_content_length(): + """ + Get default value for max content length from settings. + """ + return settings.LOG_OUTGOING_REQUESTS_MAX_CONTENT_LENGTH - save_to_db = models.IntegerField( + +class OutgoingRequestsLogConfig(SingletonModel): + """Configuration options for request logging.""" + + save_to_db = models.CharField( _("Save logs to database"), - choices=SaveLogsChoices.choices, - blank=True, - null=True, - help_text=_( - "Whether request logs should be saved to the database (default: {default})" - ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE), + max_length=11, + choices=SaveLogsChoice.choices, + default=SaveLogsChoice.use_default, ) - save_body = models.IntegerField( + save_body = models.CharField( _("Save request + response body"), - choices=SaveLogsChoices.choices, - blank=True, - null=True, + max_length=11, + choices=SaveLogsChoice.choices, + default=SaveLogsChoice.use_default, + ) + max_content_length = models.IntegerField( + _("Maximal content size"), + validators=[MinValueValidator(0)], + default=get_default_max_content_length, help_text=_( - "Wheter the body of the request and response should be logged (default: " - "{default}). This option is ignored if 'Save Logs to database' is set to " - "False." - ).format(default=settings.LOG_OUTGOING_REQUESTS_SAVE_BODY), + "The maximal size of the request/response content (in bytes). " + "If 'Require content length' is not checked, this setting has no effect." + ), ) + @property + def save_logs_enabled(self): + """ + Use configuration option or settings to determine if logs should be saved. + """ + if self.save_to_db == SaveLogsChoice.use_default: + return settings.LOG_OUTGOING_REQUESTS_DB_SAVE + return self.save_to_db == SaveLogsChoice.yes + + @property + def save_body_enabled(self): + """ + Use configuration option or settings to determine if log bodies should be saved. + """ + if self.save_body == SaveLogsChoice.use_default: + return settings.LOG_OUTGOING_REQUESTS_DB_SAVE_BODY + return self.save_body == SaveLogsChoice.yes + class Meta: - verbose_name = _("Outgoing Requests Logs Configuration") + verbose_name = _("Outgoing Requests Log Configuration") diff --git a/log_outgoing_requests/static/log_outgoing_requests/css/admin.css b/log_outgoing_requests/static/log_outgoing_requests/css/admin.css index 8485b3b..5654b4d 100644 --- a/log_outgoing_requests/static/log_outgoing_requests/css/admin.css +++ b/log_outgoing_requests/static/log_outgoing_requests/css/admin.css @@ -1,6 +1,9 @@ .field-res_body { - display: inline-block; - width: 40rem; - font-family: monospace; - line-height: 1.5rem; + display: inline-block; + width: var(--dlor-body-width, 40rem); + font-family: monospace; + line-height: 1.5rem; +} +input[name="max_content_length"] { + width: 7.25em; } diff --git a/log_outgoing_requests/templates/log_outgoing_requests/change_form.html b/log_outgoing_requests/templates/log_outgoing_requests/change_form.html new file mode 100644 index 0000000..87c5372 --- /dev/null +++ b/log_outgoing_requests/templates/log_outgoing_requests/change_form.html @@ -0,0 +1,16 @@ +{% extends "admin/change_form.html" %} + +{% block after_field_sets %} +
+
+ +
{{ log.request_body_decoded }}
+
+
+
+
+ +
{{ log.response_body_decoded }}
+
+
+{% endblock %} diff --git a/log_outgoing_requests/utils.py b/log_outgoing_requests/utils.py new file mode 100644 index 0000000..dd77739 --- /dev/null +++ b/log_outgoing_requests/utils.py @@ -0,0 +1,150 @@ +"""Tests for the utility functions""" + +import logging +from typing import TYPE_CHECKING, Iterable, Tuple, Union + +from django.conf import settings + +# header parsing must be refactored when upgrading to Django 4.2 +# Django <= 4.1: https://github.com/django/django/blob/stable/4.1.x/django/http/multipartparser.py +# Django >= 4.2: https://github.com/django/django/blob/main/django/http/multipartparser.py +from django.http.multipartparser import parse_header + +from requests import PreparedRequest, Response + +from log_outgoing_requests.datastructures import ContentType + +if TYPE_CHECKING: # pragma: nocover + from .models import OutgoingRequestsLogConfig + + +logger = logging.getLogger(__name__) + + +# +# Handler utilities +# +def _get_content_length(http_obj: Union[PreparedRequest, Response]) -> str: + """ + Try to determine the size of a request/response content. + + Try `Content-Length` header first. If not present, try to + determine the size by reading `len(body)`. The entire content + is thereby read into memory (the assumption being that the content + will eventually be consumed anyway). + """ + content_length = http_obj.headers.get("Content-Length", "") + + if not content_length: + body = http_obj.content if isinstance(http_obj, Response) else http_obj.body + if body is not None: + content_length = str(len(body)) + + return content_length + + +def check_content_length( + http_obj: Union[PreparedRequest, Response], + config: "OutgoingRequestsLogConfig", +) -> bool: + """ + Check `content_length` against settings. + + If `content_length` could not be determined (i.e. `content_length` == ""), the test + passes with a warning. + """ + content_length = _get_content_length(http_obj) + + if not content_length: + # for logging: get netloc (response) or url (request) + target = getattr(http_obj, "netloc", "") or http_obj.url + logger.warning( + "Content length of the request/response (request netloc: %s) could not be determined." + % target + ) + return True + + max_content_length = config.max_content_length + + return int(content_length) <= max_content_length + + +def parse_content_type_header( + http_obj: Union[PreparedRequest, Response] +) -> Tuple[str, str]: + """ + Wrapper around Django's `parse_header`. + + If a charset/encoding is found, we replace the representation of it with a string. + + :returns: a `tuple` (content_type, encoding) + """ + content_type_header = http_obj.headers.get("Content-Type", "") + + if not content_type_header: + return ("", "") + + # `parse_header` works on bytes, so we need to encode the header + parsed = parse_header(content_type_header.encode("utf-8")) + + # decode the (representation of the) charset/encoding back to str + encoding = parsed[1].get("charset", b"").decode("utf-8") + + return parsed[0], encoding + + +def check_content_type(content_type: str) -> bool: + """ + Check `content_type` against settings. + + The string patterns of the content types specified under `LOG_OUTGOING_REQUESTS_ + CONTENT_TYPES` are split into two groups. For regular patterns not containing a + wildcard ("text/xml"), check if `content_type.pattern` is included in the list. + For patterns containing a wildcard ("text/*"), check if `content_type.pattern` + is a substring of any pattern contained in the list. + """ + allowed_content_types: Iterable[ + ContentType + ] = settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES + regular_patterns = [ + item.pattern for item in allowed_content_types if not item.pattern.endswith("*") + ] + wildcard_patterns = [ + item.pattern for item in allowed_content_types if item.pattern.endswith("*") + ] + + if content_type in regular_patterns: + return True + + return any(content_type.startswith(pattern[:-1]) for pattern in wildcard_patterns) + + +def get_default_encoding(content_type_pattern: str) -> str: + """ + Get the default encoding for the `ContentType` with the associated pattern. + """ + allowed_content_types: Iterable[ + ContentType + ] = settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES + + regular_types = [ + item for item in allowed_content_types if not item.pattern.endswith("*") + ] + wildcard_types = [ + item for item in allowed_content_types if item.pattern.endswith("*") + ] + + content_type = next( + (item for item in regular_types if item.pattern == content_type_pattern), None + ) + if content_type is None: + content_type = next( + ( + item + for item in wildcard_types + if content_type_pattern.startswith(item.pattern[:-1]) + ), + None, + ) + + return content_type.default_encoding if content_type else "" diff --git a/setup.cfg b/setup.cfg index 5eb1286..1744db1 100644 --- a/setup.cfg +++ b/setup.cfg @@ -24,7 +24,6 @@ classifiers = Operating System :: Unix Operating System :: MacOS Operating System :: Microsoft :: Windows - Programming Language :: Python :: 3.7 Programming Language :: Python :: 3.8 Programming Language :: Python :: 3.9 Programming Language :: Python :: 3.10 @@ -35,7 +34,7 @@ zip_safe = False include_package_data = True packages = find: install_requires = - django >= 3.2 + django <= 4.1 requests django-solo tests_require = @@ -47,6 +46,7 @@ tests_require = flake8 freezegun requests-mock + pyquery [options.packages.find] include = @@ -55,8 +55,10 @@ include = [options.extras_require] tests = + psycopg2 pytest pytest-django + pyquery tox isort black diff --git a/testapp/settings.py b/testapp/settings.py index 9a91f5e..adf56b0 100644 --- a/testapp/settings.py +++ b/testapp/settings.py @@ -1,5 +1,6 @@ import os +from log_outgoing_requests.datastructures import ContentType from log_outgoing_requests.formatters import HttpFormatter BASE_DIR = os.path.abspath(os.path.dirname(__file__)) @@ -92,7 +93,16 @@ # LOG OUTGOING REQUESTS # LOG_OUTGOING_REQUESTS_DB_SAVE = True -LOG_OUTGOING_REQUESTS_SAVE_BODY = False +LOG_OUTGOING_REQUESTS_DB_SAVE_BODY = True +LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + ContentType(pattern="application/json", default_encoding="utf-8"), + ContentType(pattern="application/soap+xml", default_encoding="utf-8"), + ContentType(pattern="application/xml", default_encoding="utf-8"), + ContentType(pattern="text/xml", default_encoding="iso-8859-1"), + ContentType(pattern="text/*", default_encoding="utf-8"), +] +LOG_OUTGOING_REQUESTS_EMIT_BODY = True +LOG_OUTGOING_REQUESTS_MAX_CONTENT_LENGTH = 524_288 # 0.5 MB ROOT_URLCONF = "testapp.urls" diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..9762ff1 --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1,59 @@ +"""Global pytest fixtures""" + +import pytest + +from log_outgoing_requests.datastructures import ContentType + + +# +# default settings +# +@pytest.fixture +def default_settings(settings): + settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + ContentType(pattern="application/json", default_encoding="utf-8"), + ContentType(pattern="application/soap+xml", default_encoding="utf-8"), + ContentType(pattern="application/xml", default_encoding="utf-8"), + ContentType(pattern="text/xml", default_encoding="iso-8859-1"), + ContentType(pattern="text/*", default_encoding="utf-8"), + ] + return settings + + +# +# requests data +# +@pytest.fixture +def request_mock_kwargs(): + return { + "url": "http://example.com:8000/some-path?version=2.0", + "status_code": 200, + "json": {"test": "response data"}, + "request_headers": { + "Authorization": "test", + "Content-Type": "application/json", + "Content-Length": "24", + }, + "headers": { + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "application/json", + "Content-Length": "25", + }, + } + + +@pytest.fixture +def request_mock_kwargs_binary(): + return { + "url": "http://example.com:8000/some-path?version=2.0", + "status_code": 200, + "content": b"{\x03\xff\x00d", + "request_headers": { + "Authorization": "test", + "Content-Type": "binary", + }, + "headers": { + "Date": "Tue, 21 Mar 2023 15:24:08 GMT", + "Content-Type": "binary", + }, + } diff --git a/tests/test_admin.py b/tests/test_admin.py new file mode 100644 index 0000000..8acb674 --- /dev/null +++ b/tests/test_admin.py @@ -0,0 +1,97 @@ +"""Tests for the admin interface""" + +from datetime import datetime + +from django.urls import reverse + +import pytest +import requests +from pyquery import PyQuery + +from log_outgoing_requests.models import OutgoingRequestsLog, OutgoingRequestsLogConfig + + +# +# test display +# +@pytest.mark.django_db +def test_decoded_content_display(admin_client): + """Assert that decoded request/response bodies are properly displayed""" + + log = OutgoingRequestsLog.objects.create( + id=1, + req_body=b"I'm a lumberjack and I'm okay.", + res_body=b"I sleep all night and work all day.", + timestamp=datetime.utcnow(), + ) + url = reverse( + "admin:log_outgoing_requests_outgoingrequestslog_change", args=(log.pk,) + ) + + response = admin_client.get(url) + assert response.status_code == 200 + + html = response.content.decode("utf-8") + doc = PyQuery(html) + request_body = doc.find(".request-body-decoded").text() + response_body = doc.find(".response-body-decoded").text() + + assert request_body == "I'm a lumberjack and I'm okay." + assert response_body == "I sleep all night and work all day." + + +# +# test override of settings +# +@pytest.mark.django_db +def test_admin_override_db_save(requests_mock, request_mock_kwargs): + """Assert that saving logs can be disabled in admin""" + + config = OutgoingRequestsLogConfig.get_solo() + config.save_to_db = "no" + config.save() + + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + request_log = OutgoingRequestsLog.objects.last() + + assert request_log is None + + +@pytest.mark.django_db +def test_admin_override_save_body(requests_mock, request_mock_kwargs): + """Assert that saving body can be disabled in admin""" + + config = OutgoingRequestsLogConfig.get_solo() + config.save_body = "no" + config.save() + + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + request_log = OutgoingRequestsLog.objects.last() + + assert request_log.res_body == b"" + + +@pytest.mark.django_db +def test_admin_override_max_content_length(requests_mock, request_mock_kwargs): + """Assert that `max_content_length` can be overriden in admin""" + + config = OutgoingRequestsLogConfig.get_solo() + config.max_content_length = "10" + config.save() + + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + request_log = OutgoingRequestsLog.objects.last() + + assert request_log.res_body == b"" diff --git a/tests/test_formatter.py b/tests/test_formatter.py new file mode 100644 index 0000000..ded4c45 --- /dev/null +++ b/tests/test_formatter.py @@ -0,0 +1,46 @@ +"""Tests for the HttpFormatter helper class""" + +import logging + +import pytest +import requests + +from log_outgoing_requests.formatters import HttpFormatter + + +@pytest.mark.django_db +@pytest.mark.parametrize( + "log_body, expected", + [ + (True, True), + (False, False), + ], +) +def test_formatter( + requests_mock, + request_mock_kwargs, + caplog, + settings, + log_body, + expected, +): + """Assert that request/response bodies are (not) saved if setting is enabled (disabled)""" + + settings.LOG_OUTGOING_REQUESTS_EMIT_BODY = log_body + + formatter = HttpFormatter() + + with caplog.at_level(logging.DEBUG): + requests_mock.post(**request_mock_kwargs) + requests.post( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + record = caplog.records[1] + + res = formatter.formatMessage(record) + + assert ('{"test": "request data"}' in res) is expected + assert ('{"test": "response data"}' in res) is expected diff --git a/tests/test_logging.py b/tests/test_logging.py index fc6bc6c..f926e01 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,337 +1,244 @@ -from django.test import TestCase, override_settings +"""Integration tests for the core functionality of the library""" +import logging + +import pytest import requests -import requests_mock from freezegun import freeze_time -from log_outgoing_requests.models import OutgoingRequestsLog, OutgoingRequestsLogConfig +from log_outgoing_requests.datastructures import ContentType +from log_outgoing_requests.models import OutgoingRequestsLog + + +# +# Local pytest fixtures +# +@pytest.fixture() +def request_variants(requests_mock): + return [ + ("GET", requests.get, requests_mock.get), + ("POST", requests.post, requests_mock.post), + ("PUT", requests.put, requests_mock.put), + ("PATCH", requests.patch, requests_mock.patch), + ("DELETE", requests.delete, requests_mock.delete), + ("HEAD", requests.head, requests_mock.head), + ] + + +@pytest.fixture() +def expected_headers(): + return ( + f"User-Agent: python-requests/{requests.__version__}\n" + "Accept-Encoding: gzip, deflate\n" + "Accept: */*\n" + "Connection: keep-alive\n" + "Authorization: ***hidden***\n" + "Content-Type: application/json\n" + "Content-Length: 24" + ) + + +# +# Tests +# +@pytest.mark.django_db +def test_data_is_logged(requests_mock, request_mock_kwargs, caplog): + with caplog.at_level(logging.DEBUG): + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + records = caplog.records + assert records[1].levelname == "DEBUG" + assert records[1].name == "requests" + assert records[1].msg == "Outgoing request" -@requests_mock.Mocker() +@pytest.mark.django_db @freeze_time("2021-10-18 13:00:00") -class OutgoingRequestsLoggingTests(TestCase): - def _setUpMocks(self, m): - m.get( - "http://example.com/some-path?version=2.0", - status_code=200, - content=b"some content", +def test_data_is_saved(request_mock_kwargs, request_variants, expected_headers): + for method, request_func, request_mock in request_variants: + request_mock(**request_mock_kwargs) + response = request_func( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, ) - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - def test_outgoing_requests_are_logged(self, m): - self._setUpMocks(m) - - with self.assertLogs("requests", level="DEBUG") as logs: - requests.get("http://example.com/some-path?version=2.0") - - self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"]) - self.assertEqual(logs.records[0].name, "requests") - self.assertEqual(logs.records[0].getMessage(), "Outgoing request") - self.assertEqual(logs.records[0].levelname, "DEBUG") - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) - def test_expected_data_is_saved_when_saving_enabled(self, m): - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "text/html", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "application/json", - }, - ) - expected_req_headers = ( - f"User-Agent: python-requests/{requests.__version__}\n" - "Accept-Encoding: gzip, deflate\n" - "Accept: */*\n" - "Connection: keep-alive\n" - "Authorization: ***hidden***\n" - "Content-Type: text/html" - ) - if method not in ["HEAD", "GET"]: - expected_req_headers += "\nContent-Length: 0" - - response = func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "text/html"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertEqual( - request_log.url, "http://example.com/some-path?version=2.0" - ) - self.assertEqual(request_log.hostname, "example.com") - self.assertEqual(request_log.params, "") - self.assertEqual(request_log.query_params, "version=2.0") - self.assertEqual(response.status_code, 200) - self.assertEqual(request_log.method, method) - self.assertEqual(request_log.req_content_type, "text/html") - self.assertEqual(request_log.res_content_type, "application/json") - self.assertEqual(request_log.response_ms, 0) - self.assertEqual(request_log.req_headers, expected_req_headers) - self.assertEqual( - request_log.res_headers, - "Date: Tue, 21 Mar 2023 15:24:08 GMT\nContent-Type: application/json", - ) - self.assertEqual( - request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S"), - "2021-10-18 13:00:00", - ) - self.assertEqual(request_log.res_body[0], {"test": "data"}) - self.assertIsNone(request_log.trace) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - def test_authorization_header_is_hidden(self, m): - self._setUpMocks(m) + assert response.status_code == 200 - requests.get( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test"}, + request_log = OutgoingRequestsLog.objects.last() + + assert request_log.method == method + assert request_log.hostname == "example.com:8000" + assert request_log.params == "" + assert request_log.query_params == "version=2.0" + assert request_log.response_ms == 0 + assert request_log.trace == "" + assert str(request_log) == "example.com:8000 at 2021-10-18 13:00:00+00:00" + assert ( + request_log.timestamp.strftime("%Y-%m-%d %H:%M:%S") == "2021-10-18 13:00:00" + ) + # headers + assert request_log.req_headers == expected_headers + assert ( + request_log.res_headers == "Date: Tue, 21 Mar 2023 15:24:08 GMT\n" + "Content-Type: application/json\nContent-Length: 25" ) - log = OutgoingRequestsLog.objects.get() - - self.assertIn("Authorization: ***hidden***", log.req_headers) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False) - def test_data_is_not_saved_when_saving_disabled(self, m): - self._setUpMocks(m) - - with self.assertLogs("requests", level="DEBUG") as logs: - requests.get("http://example.com/some-path?version=2.0") - - self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"]) - self.assertEqual(logs.records[0].name, "requests") - self.assertEqual(logs.records[0].getMessage(), "Outgoing request") - self.assertEqual(logs.records[0].levelname, "DEBUG") - self.assertFalse(OutgoingRequestsLog.objects.exists()) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False) - def test_outgoing_requests_are_logged_when_saving_disabled(self, m): - self._setUpMocks(m) - - with self.assertLogs("requests", level="DEBUG") as logs: - requests.get("http://example.com/some-path?version=2.0") - - self.assertEqual(logs.output, ["DEBUG:requests:Outgoing request"]) - self.assertEqual(logs.records[0].name, "requests") - self.assertEqual(logs.records[0].getMessage(), "Outgoing request") - self.assertEqual(logs.records[0].levelname, "DEBUG") - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False) - def test_request_data_is_not_saved_when_saving_disabled(self, m): - self._setUpMocks(m) - - requests.get("http://example.com/some-path?version=2.0") - - self.assertFalse(OutgoingRequestsLog.objects.exists()) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) - def test_logging_disallowed_content_type_request(self, m): - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "video/mp4", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "text/html", - }, - ) - - func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "video/mp4"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertIsNone(request_log) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=True) - def test_logging_disallowed_content_type_response(self, m): - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "text/html", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "video/mp4", - }, - ) - - func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "text/html"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertIsNone(request_log) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) - def test_body_not_saved_when_setting_disabled(self, m): - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "text/html", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "application/json", - }, - ) - - func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "text/html"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertIsNone(request_log.res_body) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=False) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) - def test_admin_override_db_save(self, m): - config = OutgoingRequestsLogConfig.get_solo() - config.save_to_db = 1 # True - config.save() - - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "text/html", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "application/json", - }, - ) - - func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "text/html"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertIsNotNone(request_log) - self.assertIsNone(request_log.res_body) - - @override_settings(LOG_OUTGOING_REQUESTS_DB_SAVE=True) - @override_settings(LOG_OUTGOING_REQUESTS_SAVE_BODY=False) - def test_admin_override_save_body(self, m): - config = OutgoingRequestsLogConfig.get_solo() - config.save_body = 1 # True - config.save() - - methods = [ - ("GET", requests.get, m.get), - ("POST", requests.post, m.post), - ("PUT", requests.put, m.put), - ("PATCH", requests.patch, m.patch), - ("DELETE", requests.delete, m.delete), - ("HEAD", requests.head, m.head), - ] - - for method, func, mocked in methods: - with self.subTest(): - mocked( - "http://example.com/some-path?version=2.0", - status_code=200, - json={"test": "data"}, - request_headers={ - "Authorization": "test", - "Content-Type": "text/html", - }, - headers={ - "Date": "Tue, 21 Mar 2023 15:24:08 GMT", - "Content-Type": "application/json", - }, - ) - - func( - "http://example.com/some-path?version=2.0", - headers={"Authorization": "test", "Content-Type": "text/html"}, - ) - - request_log = OutgoingRequestsLog.objects.last() - - self.assertIsNotNone(request_log.res_body) + # request body + assert request_log.req_content_type == "application/json" + assert bytes(request_log.req_body) == b'{"test": "request data"}' + assert request_log.req_body_encoding == "utf-8" + # response body + assert request_log.res_content_type == "application/json" + assert bytes(request_log.res_body) == b'{"test": "response data"}' + assert request_log.res_body_encoding == "utf-8" + + +# +# test decoding of binary content +# +@pytest.mark.parametrize( + "content, encoding, expected", + [ + (b"test\x03\xff\xff{\x03}", "utf-8", "test\x03��{\x03}"), + (b"test\x03\xff\xff{\x03}", "utx-99", "test\x03��{\x03}"), + (b"test{\x03\xff\xff\x00d", "", "test{\x03��\x00d"), + ], +) +@pytest.mark.django_db +def test_decoding_of_binary_content( + content, encoding, expected, requests_mock, request_mock_kwargs_binary, settings +): + """ + Assert that decoding of binary contents works with: + - correct encoding + - wrong (e.g. misspelled) encoding + - missing encoding + """ + settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + ContentType(pattern="binary", default_encoding=encoding) + ] + + request_mock_kwargs_binary["content"] = content + + requests_mock.post(**request_mock_kwargs_binary) + response = requests.post( + request_mock_kwargs_binary["url"], + headers=request_mock_kwargs_binary["request_headers"], + data=content, + ) + + assert response.status_code == 200 + + request_log = OutgoingRequestsLog.objects.last() + + assert request_log.response_body_decoded == expected + assert request_log.request_body_decoded == expected + + +@pytest.mark.django_db +def test_authorization_header_is_hidden(requests_mock, request_mock_kwargs): + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + log = OutgoingRequestsLog.objects.get() + + assert "Authorization: ***hidden***" in log.req_headers + + +@pytest.mark.django_db +def test_disable_save_db(request_mock_kwargs, request_variants, caplog, settings): + """Assert that data is logged but not saved to DB when setting is disabled""" + + settings.LOG_OUTGOING_REQUESTS_DB_SAVE = False + + for method, request_func, request_mock in request_variants: + with caplog.at_level(logging.DEBUG): + request_mock(**request_mock_kwargs) + response = request_func( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + # data is logged + records = caplog.records + assert records[1].levelname == "DEBUG" + assert records[1].name == "requests" + assert records[1].msg == "Outgoing request" + + # data is not saved + assert OutgoingRequestsLog.objects.exists() is False + + +@pytest.mark.django_db +def test_disable_save_body(request_mock_kwargs, request_variants, settings): + """Assert that request/response bodies are not saved when setting is disabled""" + + settings.LOG_OUTGOING_REQUESTS_DB_SAVE_BODY = False + + for method, request_func, request_mock in request_variants: + request_mock(**request_mock_kwargs) + response = request_func( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + request_log = OutgoingRequestsLog.objects.last() + + assert bytes(request_log.req_body) == b"" + assert bytes(request_log.res_body) == b"" + + +@pytest.mark.django_db +def test_content_type_not_allowed(request_mock_kwargs, request_variants, settings): + """Assert that request/response bodies are not saved when content type is not allowed""" + + settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES = [ + ContentType(pattern="text/*", default_encoding="utf-8") + ] + + for method, request_func, request_mock in request_variants: + request_mock(**request_mock_kwargs) + response = request_func( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + request_log = OutgoingRequestsLog.objects.last() + + assert bytes(request_log.req_body) == b"" + assert bytes(request_log.res_body) == b"" + + +@pytest.mark.django_db +def test_content_length_exceeded(request_mock_kwargs, request_variants, settings): + """Assert that body is not saved when content-length exceeds pre-defined max""" + + settings.LOG_OUTGOING_REQUESTS_MAX_CONTENT_LENGTH = 10 + + for method, request_func, request_mock in request_variants: + request_mock(**request_mock_kwargs) + response = request_func( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + request_log = OutgoingRequestsLog.objects.last() + + assert bytes(request_log.res_body) == b"" diff --git a/tests/test_utils.py b/tests/test_utils.py new file mode 100644 index 0000000..be1bd45 --- /dev/null +++ b/tests/test_utils.py @@ -0,0 +1,167 @@ +"""Tests for the utility functions""" + +import logging + +import pytest +import requests + +from log_outgoing_requests.datastructures import ContentType +from log_outgoing_requests.models import OutgoingRequestsLogConfig +from log_outgoing_requests.utils import ( + check_content_length, + check_content_type, + get_default_encoding, + parse_content_type_header, +) + + +# +# test check_content_length +# +@pytest.mark.parametrize( + "max_content_length, expected", + [ + (1048, True), + (12, False), + ], +) +@pytest.mark.django_db +def test_check_content_length( + max_content_length, + requests_mock, + request_mock_kwargs, + expected, +): + config = OutgoingRequestsLogConfig.objects.create( + max_content_length=max_content_length, + ) + + # we check the functionality of determining missing content length + # only for the response (the requests library automatically inserts + # the content length for the request) + del request_mock_kwargs["headers"]["Content-Length"] + + mock = requests_mock.post(**request_mock_kwargs) + response = requests.post( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + result_request = check_content_length(mock.last_request, config=config) + assert result_request is expected + + result_response = check_content_length(response, config=config) + assert result_response is expected + + +# +# test parse_content_type_header +# +@pytest.mark.parametrize( + "content_type_header, expected_content_type, expected_encoding", + [ + ("text/xml; charset=us-ascii", "text/xml", "us-ascii"), + ("text/xml", "text/xml", ""), + ("application/json", "application/json", ""), + ("", "", ""), + ], +) +@pytest.mark.django_db +def test_parse_content_type_header( + content_type_header, + requests_mock, + request_mock_kwargs, + expected_content_type, + expected_encoding, +): + request_mock_kwargs["request_headers"]["Content-Type"] = content_type_header + request_mock_kwargs["headers"]["Content-Type"] = content_type_header + + mock = requests_mock.post(**request_mock_kwargs) + response = requests.post( + request_mock_kwargs["url"], + headers=request_mock_kwargs["request_headers"], + json={"test": "request data"}, + ) + + assert response.status_code == 200 + + # check request + parsed_request_header = parse_content_type_header(mock.last_request) + assert parsed_request_header[0] == expected_content_type + assert parsed_request_header[1] == expected_encoding + + # check response + parsed_response_header = parse_content_type_header(response) + assert parsed_response_header[0] == expected_content_type + assert parsed_response_header[1] == expected_encoding + + +# +# test check_content_type +# +@pytest.mark.parametrize( + "allowed_content_types, content_type_pattern, expected", + [ + ([ContentType("text/xml", "iso-8859-1")], "text/xml", True), + ([ContentType("text/xml", "iso-8859-1")], "text/html", False), + ([ContentType("text/xml", "iso-8859-1")], "video/mp4", False), + ([ContentType("text/*", "utf-8")], "text/html", True), + ], +) +@pytest.mark.django_db +def test_check_content_type( + allowed_content_types, + content_type_pattern, + expected, + settings, +): + settings.LOG_OUTGOING_REQUESTS_CONTENT_TYPES = allowed_content_types + + result = check_content_type(content_type_pattern) + assert result is expected + + +# +# test get_default_encoding +# +@pytest.mark.parametrize( + "content_type_pattern, expected", + [ + ("text/html", "utf-8"), + ("text/xml", "iso-8859-1"), + ("application/json", "utf-8"), + ("application/unknown", ""), + ], +) +@pytest.mark.django_db +def test_get_default_encoding( + content_type_pattern, + expected, +): + result = get_default_encoding(content_type_pattern) + assert result == expected + + +@pytest.mark.django_db +def test_logger_warning_missing_content_length( + requests_mock, request_mock_kwargs, caplog +): + del request_mock_kwargs["request_headers"]["Content-Length"] + + with caplog.at_level(logging.DEBUG): + requests_mock.get(**request_mock_kwargs) + requests.get( + request_mock_kwargs["url"], headers=request_mock_kwargs["request_headers"] + ) + + records = caplog.records + assert records[1].levelname == "WARNING" + assert records[1].name == "log_outgoing_requests.utils" + assert ( + records[1].msg + == "Content length of the request/response (request netloc: example.com:8000) could not be determined." + ) diff --git a/tox.ini b/tox.ini index 8dcf981..c363d71 100644 --- a/tox.ini +++ b/tox.ini @@ -1,6 +1,5 @@ [tox] envlist = - py37-django32 py{38,39,310}-django{32,41} isort black @@ -10,7 +9,6 @@ skip_missing_interpreters = true [gh-actions] python = - 3.7: py37 3.8: py38 3.9: py39 3.10: py310 @@ -24,7 +22,13 @@ DJANGO = setenv = DJANGO_SETTINGS_MODULE=testapp.settings PYTHONPATH={toxinidir} +passenv = + PGPORT + DB_USER + DB_HOST + DB_PASSWORD extras = + db tests coverage deps = @@ -55,6 +59,7 @@ basepython=python changedir=docs skipsdist=true extras = + db tests docs commands= From 09a0c0f083408485ec73a935f15a370e649ede5d Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 11:20:35 +0200 Subject: [PATCH 5/9] :wrench: Turn naive datetime warnings into errors in tests --- setup.cfg | 2 ++ 1 file changed, 2 insertions(+) diff --git a/setup.cfg b/setup.cfg index 1744db1..ea1cbe9 100644 --- a/setup.cfg +++ b/setup.cfg @@ -96,6 +96,8 @@ sections=FUTURE,STDLIB,DJANGO,THIRDPARTY,FIRSTPARTY,LOCALFOLDER [tool:pytest] testpaths = tests DJANGO_SETTINGS_MODULE=testapp.settings +filterwarnings = + error:DateTimeField .* received a naive datetime:RuntimeWarning:django.db.models.fields [pep8] [flake8] From 6e7755db63869ce1f1b9541e228dc0b12a381130 Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 11:21:58 +0200 Subject: [PATCH 6/9] :bug: Use timezone aware datetimes in test --- tests/test_admin.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/tests/test_admin.py b/tests/test_admin.py index 8acb674..5238036 100644 --- a/tests/test_admin.py +++ b/tests/test_admin.py @@ -1,8 +1,7 @@ """Tests for the admin interface""" -from datetime import datetime - from django.urls import reverse +from django.utils import timezone import pytest import requests @@ -22,7 +21,7 @@ def test_decoded_content_display(admin_client): id=1, req_body=b"I'm a lumberjack and I'm okay.", res_body=b"I sleep all night and work all day.", - timestamp=datetime.utcnow(), + timestamp=timezone.now(), ) url = reverse( "admin:log_outgoing_requests_outgoingrequestslog_change", args=(log.pk,) From 0f843fd4b0bcb4cae6ebaadb54aa2bd65c520d6c Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 11:38:37 +0200 Subject: [PATCH 7/9] :art: Clean up implementation and types --- log_outgoing_requests/admin.py | 30 +--- log_outgoing_requests/handlers.py | 146 ++++++++++-------- log_outgoing_requests/log_requests.py | 2 +- log_outgoing_requests/models.py | 32 ++-- .../log_outgoing_requests/change_form.html | 4 +- log_outgoing_requests/utils.py | 6 +- 6 files changed, 114 insertions(+), 106 deletions(-) diff --git a/log_outgoing_requests/admin.py b/log_outgoing_requests/admin.py index 353692f..bb536a7 100644 --- a/log_outgoing_requests/admin.py +++ b/log_outgoing_requests/admin.py @@ -1,10 +1,9 @@ from django import forms from django.conf import settings from django.contrib import admin -from django.shortcuts import get_object_or_404 from django.utils.translation import gettext as _ -from solo.admin import SingletonModelAdmin # type: ignore +from solo.admin import SingletonModelAdmin from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig @@ -42,45 +41,32 @@ class OutgoingRequestsLogAdmin(admin.ModelAdmin): show_full_result_count = False change_form_template = "log_outgoing_requests/change_form.html" + class Media: + css = { + "all": ("log_outgoing_requests/css/admin.css",), + } + def has_add_permission(self, request): return False def has_change_permission(self, request, obj=None): return False + @admin.display(description=_("Query parameters")) def query_params(self, obj): return obj.query_params - def change_view(self, request, object_id, extra_context=None): - """ - Add log object to to context for use in template. - """ - log = get_object_or_404(OutgoingRequestsLog, id=object_id) - - extra_context = extra_context or {} - extra_context["log"] = log - - return super().change_view(request, object_id, extra_context=extra_context) - - query_params.short_description = _("Query parameters") # type: ignore - - class Media: - css = { - "all": ("log_outgoing_requests/css/admin.css",), - } - class ConfigAdminForm(forms.ModelForm): class Meta: model = OutgoingRequestsLogConfig fields = "__all__" - widgets = {"allowed_content_types": forms.CheckboxSelectMultiple} help_texts = { "save_to_db": _( "Whether request logs should be saved to the database (default: {default})." ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE), "save_body": _( - "Wheter the body of the request and response should be logged (default: " + "Whether the body of the request and response should be logged (default: " "{default})." ).format(default=settings.LOG_OUTGOING_REQUESTS_DB_SAVE_BODY), } diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index 55d378f..07cc767 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -1,74 +1,96 @@ +# NOTE: Avoid import Django specifics at the module level to prevent circular imports. +# The handler is loaded eagerly at django startup when configuring settings. import logging import traceback +from datetime import datetime +from logging import LogRecord +from typing import Union, cast from urllib.parse import urlparse -from .utils import ( - check_content_length, - check_content_type, - get_default_encoding, - parse_content_type_header, -) +from requests.models import PreparedRequest, Response + + +class RequestLogRecord(LogRecord): + requested_at: datetime + req: PreparedRequest + res: Response + + +AnyLogRecord = Union[LogRecord, RequestLogRecord] + + +def is_request_log_record(record: AnyLogRecord) -> bool: + attrs = ("requested_at", "req", "res") + if any(not hasattr(record, attr) for attr in attrs): + return False + return True class DatabaseOutgoingRequestsHandler(logging.Handler): - def emit(self, record): + def emit(self, record: AnyLogRecord): from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig + from .utils import ( + check_content_length, + check_content_type, + get_default_encoding, + parse_content_type_header, + ) + + config = cast(OutgoingRequestsLogConfig, OutgoingRequestsLogConfig.get_solo()) + if not config.save_logs_enabled: + return + + # skip requests not coming from the library requests + if not record or not is_request_log_record(record): + return + # Typescript type predicates would be cool here :) + record = cast(RequestLogRecord, record) + + scrubbed_req_headers = record.req.headers.copy() + + if "Authorization" in scrubbed_req_headers: + scrubbed_req_headers["Authorization"] = "***hidden***" + + trace = traceback.format_exc() if record.exc_info else "" + + parsed_url = urlparse(record.req.url) + kwargs = { + "url": record.req.url, + "hostname": parsed_url.netloc, + "params": parsed_url.params, + "status_code": record.res.status_code, + "method": record.req.method, + "timestamp": record.requested_at, + "response_ms": int(record.res.elapsed.total_seconds() * 1000), + "req_headers": self.format_headers(scrubbed_req_headers), + "res_headers": self.format_headers(record.res.headers), + "trace": trace, + } + + if config.save_body_enabled: + # check request + content_type, encoding = parse_content_type_header(record.req) + if check_content_type(content_type) and check_content_length( + record.req, config + ): + kwargs["req_content_type"] = content_type + kwargs["req_body"] = record.req.body or b"" + kwargs["req_body_encoding"] = encoding or get_default_encoding( + content_type + ) + + # check response + content_type, encoding = parse_content_type_header(record.res) + if check_content_type(content_type) and check_content_length( + record.res, config + ): + kwargs["res_content_type"] = content_type + kwargs["res_body"] = record.res.content or b"" + kwargs[ + "res_body_encoding" + ] = record.res.encoding or get_default_encoding(content_type) - config = OutgoingRequestsLogConfig.get_solo() - - if config.save_logs_enabled: - trace = "" - - # skip requests not coming from the library requests - if not record or not record.getMessage() == "Outgoing request": - return - - scrubbed_req_headers = record.req.headers.copy() - - if "Authorization" in scrubbed_req_headers: - scrubbed_req_headers["Authorization"] = "***hidden***" - - if record.exc_info: - trace = traceback.format_exc() - - parsed_url = urlparse(record.req.url) - kwargs = { - "url": record.req.url, - "hostname": parsed_url.netloc, - "params": parsed_url.params, - "status_code": record.res.status_code, - "method": record.req.method, - "timestamp": record.requested_at, - "response_ms": int(record.res.elapsed.total_seconds() * 1000), - "req_headers": self.format_headers(scrubbed_req_headers), - "res_headers": self.format_headers(record.res.headers), - "trace": trace, - } - - if config.save_body_enabled: - # check request - content_type, encoding = parse_content_type_header(record.req) - if check_content_type(content_type) and check_content_length( - record.req, config - ): - kwargs["req_content_type"] = content_type - kwargs["req_body"] = record.req.body or b"" - kwargs["req_body_encoding"] = encoding or get_default_encoding( - content_type - ) - - # check response - content_type, encoding = parse_content_type_header(record.res) - if check_content_type(content_type) and check_content_length( - record.res, config - ): - kwargs["res_content_type"] = content_type - kwargs["res_body"] = record.res.content or b"" - kwargs[ - "res_body_encoding" - ] = record.res.encoding or get_default_encoding(content_type) - - OutgoingRequestsLog.objects.create(**kwargs) + OutgoingRequestsLog.objects.create(**kwargs) def format_headers(self, headers): return "\n".join(f"{k}: {v}" for k, v in headers.items()) diff --git a/log_outgoing_requests/log_requests.py b/log_outgoing_requests/log_requests.py index 5939866..f89dd79 100644 --- a/log_outgoing_requests/log_requests.py +++ b/log_outgoing_requests/log_requests.py @@ -26,7 +26,7 @@ def install_outgoing_requests_logging(): ) return - Session._initial_request = Session.request + Session._initial_request = Session.request # type: ignore def new_request(self, *args, **kwargs): self.hooks["response"].append(hook_requests_logging) diff --git a/log_outgoing_requests/models.py b/log_outgoing_requests/models.py index 89831cb..81249cb 100644 --- a/log_outgoing_requests/models.py +++ b/log_outgoing_requests/models.py @@ -1,4 +1,5 @@ import logging +from typing import Union from urllib.parse import urlparse from django.conf import settings @@ -118,35 +119,36 @@ def url_parsed(self): def query_params(self): return self.url_parsed.query - @cached_property - def request_body_decoded(self) -> str: + def _decode_body(self, content: Union[bytes, memoryview], encoding: str) -> str: """ - Decoded request body for use in template. + Decode body for use in template. If the stored encoding is not found (either because it is empty or because of spelling errors etc.), we decode "blindly", replacing chars that could not be decoded. + + Inspired on :meth:`requests.models.Response.text`, which is Apache 2.0 licensed. """ try: - decoded = str(self.req_body, self.res_body_encoding, errors="replace") + return str(content, encoding, errors="replace") except LookupError: - decoded = str(self.req_body, errors="replace") - return decoded + # A LookupError is raised if the encoding was not found which could + # indicate a misspelling or similar mistake. + return str(content, errors="replace") + + @cached_property + def request_body_decoded(self) -> str: + """ + Decoded request body for use in template. + """ + return self._decode_body(self.req_body, self.req_body_encoding) @cached_property def response_body_decoded(self) -> str: """ Decoded response body for use in template. - - If the stored encoding is not found (either because it is empty or because of - spelling errors etc.), we decode "blindly", replacing chars that could not be - decoded. """ - try: - decoded = str(self.res_body, self.res_body_encoding, errors="replace") - except LookupError: - decoded = str(self.res_body, errors="replace") - return decoded + return self._decode_body(self.res_body, self.res_body_encoding) def get_default_max_content_length(): diff --git a/log_outgoing_requests/templates/log_outgoing_requests/change_form.html b/log_outgoing_requests/templates/log_outgoing_requests/change_form.html index 87c5372..2bbabca 100644 --- a/log_outgoing_requests/templates/log_outgoing_requests/change_form.html +++ b/log_outgoing_requests/templates/log_outgoing_requests/change_form.html @@ -4,13 +4,13 @@
-
{{ log.request_body_decoded }}
+
{{ original.request_body_decoded }}
-
{{ log.response_body_decoded }}
+
{{ original.response_body_decoded }}
{% endblock %} diff --git a/log_outgoing_requests/utils.py b/log_outgoing_requests/utils.py index dd77739..1728f54 100644 --- a/log_outgoing_requests/utils.py +++ b/log_outgoing_requests/utils.py @@ -1,7 +1,7 @@ """Tests for the utility functions""" import logging -from typing import TYPE_CHECKING, Iterable, Tuple, Union +from typing import Iterable, Tuple, Union from django.conf import settings @@ -14,9 +14,7 @@ from log_outgoing_requests.datastructures import ContentType -if TYPE_CHECKING: # pragma: nocover - from .models import OutgoingRequestsLogConfig - +from .models import OutgoingRequestsLogConfig logger = logging.getLogger(__name__) From 2290817f9fdc3a2dc433ec3133380b1367ea8d6f Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 12:10:00 +0200 Subject: [PATCH 8/9] :recycle: Support Django 4.2, copy parse_header_parameters from DRF --- log_outgoing_requests/compat.py | 60 +++++++++++++++++++++++++++++++++ log_outgoing_requests/utils.py | 24 ++++--------- setup.cfg | 3 +- 3 files changed, 68 insertions(+), 19 deletions(-) create mode 100644 log_outgoing_requests/compat.py diff --git a/log_outgoing_requests/compat.py b/log_outgoing_requests/compat.py new file mode 100644 index 0000000..2992046 --- /dev/null +++ b/log_outgoing_requests/compat.py @@ -0,0 +1,60 @@ +import django + +# Taken from djangorestframework, see +# https://github.com/encode/django-rest-framework/blob/376a5cbbba3f8df9c9db8c03a7c8fa2a6e6c05f4/rest_framework/compat.py#LL156C1-L177C10 +# +# License: +# +# Copyright © 2011-present, [Encode OSS Ltd](https://www.encode.io/). +# All rights reserved. +# +# Redistribution and use in source and binary forms, with or without +# modification, are permitted provided that the following conditions are met: +# +# * Redistributions of source code must retain the above copyright notice, this +# list of conditions and the following disclaimer. +# +# * Redistributions in binary form must reproduce the above copyright notice, +# this list of conditions and the following disclaimer in the documentation +# and/or other materials provided with the distribution. +# +# * Neither the name of the copyright holder nor the names of its +# contributors may be used to endorse or promote products derived from +# this software without specific prior written permission. +# +# THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND +# ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED +# WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE +# DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE +# FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL +# DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR +# SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER +# CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, +# OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE +# OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +if django.VERSION >= (4, 2): + # Django 4.2+: use the stock parse_header_parameters function + # Note: Django 4.1 also has an implementation of parse_header_parameters + # which is slightly different from the one in 4.2, it needs + # the compatibility shim as well. + from django.utils.http import parse_header_parameters # type: ignore +else: + # Django <= 4.1: create a compatibility shim for parse_header_parameters + from django.http.multipartparser import parse_header + + def parse_header_parameters(line): + # parse_header works with bytes, but parse_header_parameters + # works with strings. Call encode to convert the line to bytes. + main_value_pair, params = parse_header(line.encode()) + return main_value_pair, { + # parse_header will convert *some* values to string. + # parse_header_parameters converts *all* values to string. + # Make sure all values are converted by calling decode on + # any remaining non-string values. + k: v if isinstance(v, str) else v.decode() + for k, v in params.items() + } + + +__all__ = ["parse_header_parameters"] diff --git a/log_outgoing_requests/utils.py b/log_outgoing_requests/utils.py index 1728f54..be54ad3 100644 --- a/log_outgoing_requests/utils.py +++ b/log_outgoing_requests/utils.py @@ -5,15 +5,10 @@ from django.conf import settings -# header parsing must be refactored when upgrading to Django 4.2 -# Django <= 4.1: https://github.com/django/django/blob/stable/4.1.x/django/http/multipartparser.py -# Django >= 4.2: https://github.com/django/django/blob/main/django/http/multipartparser.py -from django.http.multipartparser import parse_header - from requests import PreparedRequest, Response -from log_outgoing_requests.datastructures import ContentType - +from .compat import parse_header_parameters +from .datastructures import ContentType from .models import OutgoingRequestsLogConfig logger = logging.getLogger(__name__) @@ -77,18 +72,13 @@ def parse_content_type_header( :returns: a `tuple` (content_type, encoding) """ - content_type_header = http_obj.headers.get("Content-Type", "") - - if not content_type_header: + content_type_line = http_obj.headers.get("Content-Type", "") + if not content_type_line: return ("", "") - # `parse_header` works on bytes, so we need to encode the header - parsed = parse_header(content_type_header.encode("utf-8")) - - # decode the (representation of the) charset/encoding back to str - encoding = parsed[1].get("charset", b"").decode("utf-8") - - return parsed[0], encoding + content_type, params = parse_header_parameters(content_type_line) + encoding = params.get("charset", "") + return content_type, encoding def check_content_type(content_type: str) -> bool: diff --git a/setup.cfg b/setup.cfg index ea1cbe9..5598da6 100644 --- a/setup.cfg +++ b/setup.cfg @@ -34,7 +34,7 @@ zip_safe = False include_package_data = True packages = find: install_requires = - django <= 4.1 + django >= 3.2 requests django-solo tests_require = @@ -55,7 +55,6 @@ include = [options.extras_require] tests = - psycopg2 pytest pytest-django pyquery From b8d6edb100471080d2d4bf1b7cc2c9e3f98d84f3 Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 12:28:54 +0200 Subject: [PATCH 9/9] :recycle: Reduce code duplication --- log_outgoing_requests/datastructures.py | 9 ++++++ log_outgoing_requests/handlers.py | 41 +++++++++++-------------- log_outgoing_requests/utils.py | 37 +++++++++++++++++----- 3 files changed, 57 insertions(+), 30 deletions(-) diff --git a/log_outgoing_requests/datastructures.py b/log_outgoing_requests/datastructures.py index 9ee6a36..136b69a 100644 --- a/log_outgoing_requests/datastructures.py +++ b/log_outgoing_requests/datastructures.py @@ -6,6 +6,7 @@ """ from dataclasses import dataclass +from typing import Union @dataclass @@ -16,3 +17,11 @@ class ContentType: pattern: str default_encoding: str + + +@dataclass +class ProcessedBody: + allow_saving_to_db: bool + content: Union[bytes, str] + content_type: str + encoding: str diff --git a/log_outgoing_requests/handlers.py b/log_outgoing_requests/handlers.py index 07cc767..f067be2 100644 --- a/log_outgoing_requests/handlers.py +++ b/log_outgoing_requests/handlers.py @@ -29,12 +29,7 @@ def is_request_log_record(record: AnyLogRecord) -> bool: class DatabaseOutgoingRequestsHandler(logging.Handler): def emit(self, record: AnyLogRecord): from .models import OutgoingRequestsLog, OutgoingRequestsLogConfig - from .utils import ( - check_content_length, - check_content_type, - get_default_encoding, - parse_content_type_header, - ) + from .utils import process_body config = cast(OutgoingRequestsLogConfig, OutgoingRequestsLogConfig.get_solo()) if not config.save_logs_enabled: @@ -69,26 +64,26 @@ def emit(self, record: AnyLogRecord): if config.save_body_enabled: # check request - content_type, encoding = parse_content_type_header(record.req) - if check_content_type(content_type) and check_content_length( - record.req, config - ): - kwargs["req_content_type"] = content_type - kwargs["req_body"] = record.req.body or b"" - kwargs["req_body_encoding"] = encoding or get_default_encoding( - content_type + processed_request_body = process_body(record.req, config) + if processed_request_body.allow_saving_to_db: + kwargs.update( + { + "req_content_type": processed_request_body.content_type, + "req_body": processed_request_body.content, + "req_body_encoding": processed_request_body.encoding, + } ) # check response - content_type, encoding = parse_content_type_header(record.res) - if check_content_type(content_type) and check_content_length( - record.res, config - ): - kwargs["res_content_type"] = content_type - kwargs["res_body"] = record.res.content or b"" - kwargs[ - "res_body_encoding" - ] = record.res.encoding or get_default_encoding(content_type) + processed_response_body = process_body(record.res, config) + if processed_response_body.allow_saving_to_db: + kwargs.update( + { + "res_content_type": processed_response_body.content_type, + "res_body": processed_response_body.content, + "res_body_encoding": processed_response_body.encoding, + } + ) OutgoingRequestsLog.objects.create(**kwargs) diff --git a/log_outgoing_requests/utils.py b/log_outgoing_requests/utils.py index be54ad3..80b6d38 100644 --- a/log_outgoing_requests/utils.py +++ b/log_outgoing_requests/utils.py @@ -8,16 +8,41 @@ from requests import PreparedRequest, Response from .compat import parse_header_parameters -from .datastructures import ContentType +from .datastructures import ContentType, ProcessedBody from .models import OutgoingRequestsLogConfig logger = logging.getLogger(__name__) +HttpObj = Union[PreparedRequest, Response] + + +def process_body(http_obj: HttpObj, config: OutgoingRequestsLogConfig) -> ProcessedBody: + """ + Process a request or response body by parsing the meta information. + """ + content_type, encoding = parse_content_type_header(http_obj) + if not encoding: + encoding = get_default_encoding(content_type) + allow_persisting = check_content_type(content_type) and check_content_length( + http_obj, config=config + ) + content = _get_body(http_obj) if allow_persisting else b"" + return ProcessedBody( + allow_saving_to_db=allow_persisting, + content=content or b"", + content_type=content_type, + encoding=encoding, + ) + # # Handler utilities # -def _get_content_length(http_obj: Union[PreparedRequest, Response]) -> str: +def _get_body(http_obj: HttpObj) -> Union[bytes, str, None]: + return http_obj.content if isinstance(http_obj, Response) else http_obj.body + + +def _get_content_length(http_obj: HttpObj) -> str: """ Try to determine the size of a request/response content. @@ -29,7 +54,7 @@ def _get_content_length(http_obj: Union[PreparedRequest, Response]) -> str: content_length = http_obj.headers.get("Content-Length", "") if not content_length: - body = http_obj.content if isinstance(http_obj, Response) else http_obj.body + body = _get_body(http_obj) if body is not None: content_length = str(len(body)) @@ -37,7 +62,7 @@ def _get_content_length(http_obj: Union[PreparedRequest, Response]) -> str: def check_content_length( - http_obj: Union[PreparedRequest, Response], + http_obj: HttpObj, config: "OutgoingRequestsLogConfig", ) -> bool: """ @@ -62,9 +87,7 @@ def check_content_length( return int(content_length) <= max_content_length -def parse_content_type_header( - http_obj: Union[PreparedRequest, Response] -) -> Tuple[str, str]: +def parse_content_type_header(http_obj: HttpObj) -> Tuple[str, str]: """ Wrapper around Django's `parse_header`.