Merge pull request #3074 from open-formulieren/feature/2762-request-l…

…ogging

[#2762] update settings: log outgoing requests

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
 

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

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

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

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

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

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

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
+"""

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

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

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",
@@ -361,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")
 
@@ -376,6 +381,7 @@
         "performance": {
             "format": "%(asctime)s %(process)d | %(thread)d | %(message)s",
         },
+        "outgoing_requests": {"()": HttpFormatter},
     },
     "filters": {
         "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"},
@@ -419,6 +425,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 +460,13 @@
             "handlers": ["project"] if not LOG_STDOUT else ["console"],
             "level": "DEBUG",
         },
+        "requests": {
+            "handlers": ["log_outgoing_requests", "save_outgoing_requests"]
+            if LOG_REQUESTS
+            else [],
+            "level": "DEBUG",
+            "propagate": True,
+        },
     },
 }
 
@@ -679,6 +701,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 +1167,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
 #

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
 

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