From 6b46ff5708df358de1c64c644d41cecc0130a524 Mon Sep 17 00:00:00 2001 From: Paul Schilling Date: Tue, 2 May 2023 12:55:48 +0200 Subject: [PATCH 1/5] :loud_sound: [#2762] -- add logging for outgoing requests --- requirements/base.in | 1 + requirements/base.txt | 6 +++ requirements/ci.txt | 8 ++++ requirements/dev.txt | 8 ++++ requirements/extensions.txt | 8 ++++ src/log_outgoing_requests_ext/__init__.py | 6 +++ src/log_outgoing_requests_ext/tasks.py | 21 ++++++++++ .../tests/__init__.py | 0 .../tests/test_tasks.py | 25 +++++++++++ src/openforms/conf/base.py | 41 +++++++++++++++++++ 10 files changed, 124 insertions(+) create mode 100644 src/log_outgoing_requests_ext/__init__.py create mode 100644 src/log_outgoing_requests_ext/tasks.py create mode 100644 src/log_outgoing_requests_ext/tests/__init__.py create mode 100644 src/log_outgoing_requests_ext/tests/test_tasks.py diff --git a/requirements/base.in b/requirements/base.in index 022dd9f805..87b6380fc4 100644 --- a/requirements/base.in +++ b/requirements/base.in @@ -49,6 +49,7 @@ django-cors-headers django-decorator-include django-digid-eherkenning django-hijack +django-log-outgoing-requests django-modeltranslation django-ordered-model django-privates diff --git a/requirements/base.txt b/requirements/base.txt index 74f93fa268..5ec89dbb39 100644 --- a/requirements/base.txt +++ b/requirements/base.txt @@ -103,6 +103,7 @@ django==3.2.19 # django-filter # django-formtools # django-hijack + # django-log-outgoing-requests # django-modeltranslation # django-otp # django-phonenumber-field @@ -131,6 +132,7 @@ django-admin-index==2.0.0 django-appconf==1.0.4 # via # django-cookie-consent + # django-log-outgoing-requests # django-timeline-logger django-autoslug==1.9.8 # via -r requirements/base.in @@ -166,6 +168,8 @@ django-hijack==3.1.6 # via -r requirements/base.in django-ipware==3.0.1 # via django-axes +django-log-outgoing-requests==0.4.0 + # via -r requirements/base.in django-modeltranslation==0.18.5 # via -r requirements/base.in django-ordered-model==3.6 @@ -197,6 +201,7 @@ django-solo==2.0.0 # -r requirements/base.in # django-camunda # django-digid-eherkenning + # django-log-outgoing-requests # mozilla-django-oidc-db # zgw-consumers django-timeline-logger==2.1.0 @@ -376,6 +381,7 @@ redis==4.5.4 requests==2.31.0 # via # django-camunda + # django-log-outgoing-requests # gemma-zds-client # maykin-python3-saml # mozilla-django-oidc diff --git a/requirements/ci.txt b/requirements/ci.txt index b7e77a7c3b..42a35c51c0 100644 --- a/requirements/ci.txt +++ b/requirements/ci.txt @@ -178,6 +178,7 @@ django==3.2.19 # django-formtools # django-hijack # django-jenkins + # django-log-outgoing-requests # django-modeltranslation # django-otp # django-phonenumber-field @@ -210,6 +211,7 @@ django-appconf==1.0.4 # -c requirements/base.txt # -r requirements/base.txt # django-cookie-consent + # django-log-outgoing-requests # django-timeline-logger django-autoslug==1.9.8 # via @@ -280,6 +282,10 @@ django-ipware==3.0.1 # django-axes django-jenkins==0.110.0 # via -r requirements/test-tools.in +django-log-outgoing-requests==0.4.0 + # via + # -c requirements/base.txt + # -r requirements/base.txt django-modeltranslation==0.18.5 # via # -c requirements/base.txt @@ -335,6 +341,7 @@ django-solo==2.0.0 # -r requirements/base.txt # django-camunda # django-digid-eherkenning + # django-log-outgoing-requests # mozilla-django-oidc-db # zgw-consumers django-timeline-logger==2.1.0 @@ -725,6 +732,7 @@ requests==2.31.0 # -c requirements/base.txt # -r requirements/base.txt # django-camunda + # django-log-outgoing-requests # gemma-zds-client # maykin-python3-saml # mozilla-django-oidc diff --git a/requirements/dev.txt b/requirements/dev.txt index 2146653d0b..d6f2f51eaf 100644 --- a/requirements/dev.txt +++ b/requirements/dev.txt @@ -205,6 +205,7 @@ django==3.2.19 # django-formtools # django-hijack # django-jenkins + # django-log-outgoing-requests # django-modeltranslation # django-otp # django-phonenumber-field @@ -239,6 +240,7 @@ django-appconf==1.0.4 # -c requirements/ci.txt # -r requirements/ci.txt # django-cookie-consent + # django-log-outgoing-requests # django-timeline-logger django-autoslug==1.9.8 # via @@ -315,6 +317,10 @@ django-jenkins==0.110.0 # via # -c requirements/ci.txt # -r requirements/ci.txt +django-log-outgoing-requests==0.4.0 + # via + # -c requirements/ci.txt + # -r requirements/ci.txt django-modeltranslation==0.18.5 # via # -c requirements/ci.txt @@ -374,6 +380,7 @@ django-solo==2.0.0 # -r requirements/ci.txt # django-camunda # django-digid-eherkenning + # django-log-outgoing-requests # mozilla-django-oidc-db # zgw-consumers django-timeline-logger==2.1.0 @@ -858,6 +865,7 @@ requests==2.31.0 # -r requirements/ci.txt # ddt-api-calls # django-camunda + # django-log-outgoing-requests # django-rosetta # django-silk # gemma-zds-client diff --git a/requirements/extensions.txt b/requirements/extensions.txt index baa57599de..2133273e23 100644 --- a/requirements/extensions.txt +++ b/requirements/extensions.txt @@ -142,6 +142,7 @@ django==3.2.19 # django-filter # django-formtools # django-hijack + # django-log-outgoing-requests # django-modeltranslation # django-otp # django-phonenumber-field @@ -174,6 +175,7 @@ django-appconf==1.0.4 # via # -r requirements/base.txt # django-cookie-consent + # django-log-outgoing-requests # django-timeline-logger django-autoslug==1.9.8 # via @@ -240,6 +242,10 @@ django-ipware==3.0.1 # via # -r requirements/base.txt # django-axes +django-log-outgoing-requests==0.4.0 + # via + # -c requirements/base.in + # -r requirements/base.txt django-modeltranslation==0.18.5 # via # -c requirements/base.in @@ -289,6 +295,7 @@ django-solo==2.0.0 # -r requirements/base.txt # django-camunda # django-digid-eherkenning + # django-log-outgoing-requests # mozilla-django-oidc-db # zgw-consumers django-timeline-logger==2.1.0 @@ -579,6 +586,7 @@ requests==2.31.0 # via # -r requirements/base.txt # django-camunda + # django-log-outgoing-requests # gemma-zds-client # maykin-python3-saml # mozilla-django-oidc diff --git a/src/log_outgoing_requests_ext/__init__.py b/src/log_outgoing_requests_ext/__init__.py new file mode 100644 index 0000000000..e9c7cf2138 --- /dev/null +++ b/src/log_outgoing_requests_ext/__init__.py @@ -0,0 +1,6 @@ +""" +Extensions on top of django-log-outgoing-requests + +TODO: move this (or parts) into the library itself, see +https://github.com/maykinmedia/django-log-outgoing-requests/issues/7 +""" diff --git a/src/log_outgoing_requests_ext/tasks.py b/src/log_outgoing_requests_ext/tasks.py new file mode 100644 index 0000000000..413f1ae1ee --- /dev/null +++ b/src/log_outgoing_requests_ext/tasks.py @@ -0,0 +1,21 @@ +import logging +from datetime import timedelta + +from django.conf import settings +from django.utils import timezone + +from celery import shared_task +from log_outgoing_requests.models import OutgoingRequestsLog + +logger = logging.getLogger(__name__) + + +@shared_task +def cleanup_request_logs() -> int: + delta = timedelta(hours=settings.LOG_OUTGOING_REQUESTS_MAX_AGE) + past_timestamp = timezone.now() - delta + num_deleted, _ = OutgoingRequestsLog.objects.filter( + timestamp__lte=past_timestamp + ).delete() + logger.info("Deleted %d outgoing request log(s)", num_deleted) + return num_deleted diff --git a/src/log_outgoing_requests_ext/tests/__init__.py b/src/log_outgoing_requests_ext/tests/__init__.py new file mode 100644 index 0000000000..e69de29bb2 diff --git a/src/log_outgoing_requests_ext/tests/test_tasks.py b/src/log_outgoing_requests_ext/tests/test_tasks.py new file mode 100644 index 0000000000..e81c604ebf --- /dev/null +++ b/src/log_outgoing_requests_ext/tests/test_tasks.py @@ -0,0 +1,25 @@ +from django.test import TestCase, override_settings +from django.utils import timezone + +from freezegun import freeze_time +from log_outgoing_requests.models import OutgoingRequestsLog + +from ..tasks import cleanup_request_logs + + +class TestLogTask(TestCase): + @override_settings(LOG_OUTGOING_REQUESTS_MAX_AGE=1) # delete if >= one hour old + def test_cleanup_request_logs(self): + """Assert that logs are cleaned if and only if created before specified time""" + with freeze_time("2023-06-08T22:00:00Z") as frozen_time: + OutgoingRequestsLog.objects.create(timestamp=timezone.now()) + frozen_time.move_to("2023-06-08T23:15:00Z") + to_keep = OutgoingRequestsLog.objects.create(timestamp=timezone.now()) + + cleanup_request_logs() + + self.assertQuerysetEqual( + OutgoingRequestsLog.objects.all(), + [to_keep.pk], + transform=lambda record: record.pk, + ) diff --git a/src/openforms/conf/base.py b/src/openforms/conf/base.py index 07fd976790..954a4ff5ad 100644 --- a/src/openforms/conf/base.py +++ b/src/openforms/conf/base.py @@ -8,6 +8,8 @@ import sentry_sdk from celery.schedules import crontab from corsheaders.defaults import default_headers as default_cors_headers +from log_outgoing_requests.datastructures import ContentType +from log_outgoing_requests.formatters import HttpFormatter from csp_post_processor.constants import NONCE_HTTP_HEADER @@ -185,6 +187,8 @@ "cspreports", "csp_post_processor", "django_camunda", + "log_outgoing_requests", + "log_outgoing_requests_ext", # Project applications. "openforms.accounts", "openforms.analytics_tools", @@ -376,6 +380,7 @@ "performance": { "format": "%(asctime)s %(process)d | %(thread)d | %(message)s", }, + "outgoing_requests": {"()": HttpFormatter}, }, "filters": { "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"}, @@ -419,6 +424,15 @@ "maxBytes": 1024 * 1024 * 10, # 10 MB "backupCount": 10, }, + "log_outgoing_requests": { + "level": "DEBUG", + "formatter": "outgoing_requests", + "class": "logging.StreamHandler", + }, + "save_outgoing_requests": { + "level": "DEBUG", + "class": "log_outgoing_requests.handlers.DatabaseOutgoingRequestsHandler", + }, }, "loggers": { "openforms": { @@ -445,6 +459,11 @@ "handlers": ["project"] if not LOG_STDOUT else ["console"], "level": "DEBUG", }, + "requests": { + "handlers": ["log_outgoing_requests", "save_outgoing_requests"], + "level": "DEBUG", + "propagate": True, + }, }, } @@ -679,6 +698,10 @@ "task": "openforms.forms.admin.tasks.clear_forms_export", "schedule": crontab(hour=0, minute=0, day_of_week="sunday"), }, + "cleanup-outgoing-request-logs": { + "task": "log_outgoing_requests_ext.tasks.cleanup_request_logs", + "schedule": crontab(hour=0, minute=0, day_of_week="*"), + }, } RETRY_SUBMISSIONS_TIME_LIMIT = config( @@ -1141,6 +1164,24 @@ # MODELTRANSLATION_DEFAULT_LANGUAGE = "nl" +# +# Django-log-outgoing-requests +# +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.5MB + +# Custom settings +LOG_OUTGOING_REQUESTS_MAX_AGE = config( + "LOG_OUTGOING_REQUESTS_MAX_AGE", default=7 * 24 +) # number of hours + # # Open Forms extensions # From c90cfa01f8ff8eda6749d4abac49c596e6e6a2fc Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 23:11:43 +0200 Subject: [PATCH 2/5] :bento: [#2762] -- update admin index fixture --- src/openforms/fixtures/default_admin_index.json | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/openforms/fixtures/default_admin_index.json b/src/openforms/fixtures/default_admin_index.json index 37fca155d4..2f7f530be0 100644 --- a/src/openforms/fixtures/default_admin_index.json +++ b/src/openforms/fixtures/default_admin_index.json @@ -190,6 +190,10 @@ "django_yubin", "blacklist" ], + [ + "log_outgoing_requests", + "outgoingrequestslogconfig" + ], [ "multidomain", "domain" @@ -268,6 +272,10 @@ "logging", "timelinelogproxy" ], + [ + "log_outgoing_requests", + "outgoingrequestslog" + ], [ "submissions", "temporaryfileupload" From 297fef093acd14dc03733364bcd02e103ad2e153 Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Thu, 8 Jun 2023 23:16:38 +0200 Subject: [PATCH 3/5] :hammer: Do not log requests in docs build/tests --- docs/conf.py | 1 + src/openforms/conf/base.py | 5 ++++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/docs/conf.py b/docs/conf.py index bbd902fd68..f674007650 100644 --- a/docs/conf.py +++ b/docs/conf.py @@ -11,6 +11,7 @@ import django sys.path.insert(0, os.path.abspath("../src")) +os.environ["LOG_REQUESTS"] = "false" import openforms # noqa isort:skip diff --git a/src/openforms/conf/base.py b/src/openforms/conf/base.py index 954a4ff5ad..3b2a8d5c04 100644 --- a/src/openforms/conf/base.py +++ b/src/openforms/conf/base.py @@ -365,6 +365,7 @@ # LOGGING # LOG_STDOUT = config("LOG_STDOUT", default=False) +LOG_REQUESTS = config("LOG_REQUESTS", default=True) LOGGING_DIR = os.path.join(BASE_DIR, "log") @@ -460,7 +461,9 @@ "level": "DEBUG", }, "requests": { - "handlers": ["log_outgoing_requests", "save_outgoing_requests"], + "handlers": ["log_outgoing_requests", "save_outgoing_requests"] + if LOG_REQUESTS + else [], "level": "DEBUG", "propagate": True, }, From c35626100a74628acede05a1a0f642101d2ce114 Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Fri, 9 Jun 2023 10:59:46 +0200 Subject: [PATCH 4/5] :green_heart: [#2762] -- disable requests logging in tests/CI --- docs/developers/backend/tests.rst | 26 ++++++++++++++++++++++++++ src/openforms/conf/ci.py | 6 ++++++ src/openforms/conf/dev.py | 3 +++ 3 files changed, 35 insertions(+) diff --git a/docs/developers/backend/tests.rst b/docs/developers/backend/tests.rst index e940bb3cab..034fd21159 100644 --- a/docs/developers/backend/tests.rst +++ b/docs/developers/backend/tests.rst @@ -107,3 +107,29 @@ Example custom command: NO_E2E_HEADLESS=1 E2E_DRIVER=firefox python src/manage.py test src --tag=e2e .. note:: Only the presence of the ``NO_E2E_HEADLESS`` is checked, not the value + +Known issues +============ + +**AssertionError: Database queries to 'default' are not allowed in SimpleTestCase subclasses.** + +These are often caused by django-solo ``SingletonModel`` sucblasses that are being +called somewhere, e.g. ``GlobalConfiguration.get_solo``. Sometimes they fetch from +cache, sometimes there is a cache miss and a database query is needed (e.g. when running +tests in reverse). + +This is typically a test-isolation smell and the root cause should be fixed. This may +also be caused indirectly if you have ``LOG_REQUESTS`` set to ``True`` in your local +``.env``, as it also results in a django-solo lookup. + +The preferred approach to mitigate these kind of issues is to mock the ``get_solo`` call +to prevent cache or DB hits: + +.. code-block:: python + + @unittest.mock.patch( + "path.to.module.using_the_model.GlobalConfiguration.get_solo", + return_value=GlobalConfiguration(...), + ) + def test_something(self, mock_get_solo): + ... diff --git a/src/openforms/conf/ci.py b/src/openforms/conf/ci.py index 5284e49338..75620e9ff7 100644 --- a/src/openforms/conf/ci.py +++ b/src/openforms/conf/ci.py @@ -8,6 +8,12 @@ os.environ.setdefault("IS_HTTPS", "no") os.environ.setdefault("SECRET_KEY", "dummy") +# Do not log requests in CI/tests: +# +# * overhead making tests slower +# * it conflicts with SimpleTestCase in some cases when the run-time configuration is +# looked up from the django-solo model +os.environ.setdefault("LOG_REQUESTS", "no") from .base import * # noqa isort:skip diff --git a/src/openforms/conf/dev.py b/src/openforms/conf/dev.py index 58f7f492ba..2cede36e57 100644 --- a/src/openforms/conf/dev.py +++ b/src/openforms/conf/dev.py @@ -22,6 +22,9 @@ ) os.environ.setdefault("RELEASE", "dev") os.environ.setdefault("SDK_RELEASE", "latest") +# otherwise the test suite is flaky due to logging config lookups to the DB in +# non-DB test cases +os.environ.setdefault("LOG_REQUESTS", "no") from .base import * # noqa isort:skip From c579a316d3a56398ae5e76dff2cc0c4be853f0b9 Mon Sep 17 00:00:00 2001 From: Sergei Maertens Date: Fri, 9 Jun 2023 12:35:13 +0200 Subject: [PATCH 5/5] :lipstick: [#2762] -- properly align log request/response bodies When the content is too wide, with float it wraps onto the next line. Using flexbox ensures this doesn't happen. --- src/openforms/scss/admin/_app_overrides.scss | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) diff --git a/src/openforms/scss/admin/_app_overrides.scss b/src/openforms/scss/admin/_app_overrides.scss index 150f9c41eb..14fe230d63 100644 --- a/src/openforms/scss/admin/_app_overrides.scss +++ b/src/openforms/scss/admin/_app_overrides.scss @@ -235,3 +235,23 @@ body.app-forms.model-category.change-list { padding: 8px 10px; } } + +/** + * Django-log-outgoing-requests + */ +body.app-log_outgoing_requests.model-outgoingrequestslog { + .field-request_body, + .field-response_body { + & > div { + display: flex; + } + + .readonly { + white-space: pre-wrap !important; + max-width: 88ch; + overflow: unset !important; + word-break: break-all; + overflow-wrap: anywhere; + } + } +}