Merge pull request #4060 from open-formulieren/chore/suppress-logging…

…-output-in-tests

Fixed log output suppression when running tests locally

src/openforms/conf/base.py

@@ -386,9 +386,6 @@
         },
         "timestamped": {"format": "%(asctime)s %(levelname)s %(name)s  %(message)s"},
         "simple": {"format": "%(levelname)s  %(message)s"},
-        "performance": {
-            "format": "%(asctime)s %(process)d | %(thread)d | %(message)s",
-        },
         "outgoing_requests": {"()": HttpFormatter},
     },
     "filters": {
@@ -425,14 +422,6 @@
             "maxBytes": 1024 * 1024 * 10,  # 10 MB
             "backupCount": 10,
         },
-        "performance": {
-            "level": "INFO",
-            "class": "logging.handlers.RotatingFileHandler",
-            "filename": os.path.join(LOGGING_DIR, "performance.log"),
-            "formatter": "performance",
-            "maxBytes": 1024 * 1024 * 10,  # 10 MB
-            "backupCount": 10,
-        },
         "log_outgoing_requests": {
             "level": "DEBUG",
             "formatter": "outgoing_requests",
@@ -446,7 +435,7 @@
     "loggers": {
         "openforms": {
             "handlers": ["project"] if not LOG_STDOUT else ["console"],
-            "level": "DEBUG",
+            "level": "INFO",
             "propagate": True,
         },
         "stuf": {
@@ -466,7 +455,7 @@
         },
         "mozilla_django_oidc": {
             "handlers": ["project"] if not LOG_STDOUT else ["console"],
-            "level": "DEBUG",
+            "level": "INFO",
         },
         "log_outgoing_requests": {
             "handlers": (

src/openforms/conf/dev.py

@@ -25,6 +25,7 @@
 # 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")
+os.environ.setdefault("LOG_STDOUT", "1")
 os.environ.setdefault("VCR_RECORD_MODE", "once")
 
 from .base import *  # noqa isort:skip
@@ -40,30 +41,15 @@
 
 LOGGING["loggers"].update(
     {
-        "openforms": {
-            "handlers": ["console"],
-            "level": "DEBUG",
-            "propagate": True,
-        },
-        "stuf": {
-            "handlers": ["console"],
-            "level": "DEBUG",
-            "propagate": True,
-        },
         "django": {
             "handlers": ["console"],
             "level": "DEBUG",
-            "propagate": True,
+            "propagate": False,
         },
         "django.db.backends": {
             "handlers": ["django"],
-            "level": "DEBUG",
-            "propagate": False,
-        },
-        "performance": {
-            "handlers": ["console"],
             "level": "INFO",
-            "propagate": True,
+            "propagate": False,
         },
         #
         # See: https://code.djangoproject.com/ticket/30554
@@ -77,7 +63,7 @@
         "weasyprint": {
             "handlers": ["console"],
             "level": "DEBUG",
-            "propagate": True,
+            "propagate": False,
         },
     }
 )

src/openforms/conf/local_example.py

@@ -4,8 +4,8 @@
 import os
 import sys
 
-from .dev import LOGGING as _LOGGING
-from .utils import config
+from .dev import LOGGING
+from .utils import config, mute_logging
 
 # Configure your database via the DB_* envvars in .env, see also dotenv.example file.
 
@@ -21,22 +21,32 @@
 
     # Silence logging during testing
     # if "VERBOSE" not in os.environ:
-    #     LOGGING = None
+    #     mute_logging(LOGGING)
 
 
-if "CELERY_TASK_ALWAYS_EAGER" in os.environ:
+# run celery tasks so submissions get processed in dev server
+# Ceveat emptor: this breaks test isolation and breaks a few tests in the suite
+if config("CELERY_TASK_ALWAYS_EAGER", default=False):
     CELERY_TASK_ALWAYS_EAGER = True
 
+#
+# LOGGING
+#
+
+# Log DB queries to file and console
+# LOGGING["loggers"]["django.db.backends"] = {
+#     "handlers": ["django", "console"],
+#     "level": "DEBUG",
+#     "propagate": False,
+# }
+
 if log_level := os.environ.get("LOG_LEVEL"):
-    for logger in _LOGGING["loggers"].values():
+    for logger in LOGGING["loggers"].values():
         logger["level"] = log_level
 
+
 # make the language code configurable via envvars
 LANGUAGE_CODE = config("LANGUAGE_CODE", "nl")
 
 # allow SPA dev server and API on different ports
 # CORS_ALLOW_ALL_ORIGINS = True
-
-# run celery tasks so submissions get processed in dev server
-# Ceveat emptor: this breaks test isolation and breaks a few tests in the suite
-# CELERY_TASK_ALWAYS_EAGER = True

src/openforms/conf/utils.py

@@ -111,3 +111,23 @@ def get_sentry_integrations() -> list:
         extra.append(celery.CeleryIntegration())
 
     return [*default, *extra]
+
+
+def mute_logging(config: dict) -> None:  # pragma: no cover
+    """
+    Disable (console) output from logging.
+
+    :arg config: The logging config, typically the django LOGGING setting.
+    """
+
+    # set up the null handler for all loggers so that nothing gets emitted
+    for logger in config["loggers"].values():
+        logger["handlers"] = ["null"]
+
+    # some tooling logs to a logger which isn't defined, and that ends up in the root
+    # logger -> add one so that we can mute that output too.
+    config["loggers"].update(
+        {
+            "": {"handlers": ["null"], "level": "CRITICAL", "propagate": False},
+        }
+    )

src/openforms/registrations/tests/test_pre_registration.py

@@ -14,6 +14,7 @@
 from openforms.submissions.constants import PostSubmissionEvents
 from openforms.submissions.tasks.registration import pre_registration
 from openforms.submissions.tests.factories import SubmissionFactory
+from openforms.utils.tests.logging import ensure_logger_level
 
 
 class PreRegistrationTests(TestCase):
@@ -272,6 +273,7 @@ def test_retry_after_too_many_attempts_skips(self, m_get_solo):
             patch(
                 "openforms.registrations.contrib.zgw_apis.plugin.ZGWRegistration.pre_register_submission"
             ) as mock_pre_register,
+            ensure_logger_level("DEBUG"),
             self.assertLogs(level="DEBUG") as logs,
         ):
             pre_registration(submission.id, PostSubmissionEvents.on_retry)

src/openforms/registrations/tests/test_registration_hook.py

@@ -19,6 +19,7 @@
 from openforms.logging.models import TimelineLogProxy
 from openforms.submissions.constants import PostSubmissionEvents, RegistrationStatuses
 from openforms.submissions.tests.factories import SubmissionFactory
+from openforms.utils.tests.logging import ensure_logger_level
 
 from ..base import BasePlugin
 from ..exceptions import RegistrationFailed
@@ -286,6 +287,7 @@ def register_submission(self, submission, options):
 
             with self.subTest("on retry"):
                 with (
+                    ensure_logger_level("DEBUG"),
                     self.assertRaises(RegistrationFailed),
                     self.assertLogs(level="DEBUG") as logs,
                 ):

src/openforms/submissions/tests/test_post_submission_event.py

@@ -16,6 +16,7 @@
 from openforms.forms.tests.factories import FormDefinitionFactory
 from openforms.payments.constants import PaymentStatus
 from openforms.payments.tests.factories import SubmissionPaymentFactory
+from openforms.utils.tests.logging import ensure_logger_level
 
 from ..constants import PostSubmissionEvents
 from ..models import SubmissionReport
@@ -1058,6 +1059,7 @@ def test_payment_required_and_not_should_wait_for_registration(self):
                 "openforms.registrations.tasks.GlobalConfiguration.get_solo",
                 return_value=GlobalConfiguration(wait_for_payment_to_register=True),
             ),
+            ensure_logger_level("DEBUG"),
             LogCapture() as logs,
         ):
             on_post_submission_event(submission.id, PostSubmissionEvents.on_completion)

src/openforms/utils/tests/logging.py

@@ -1,4 +1,6 @@
 import logging
+from contextlib import contextmanager
+from typing import Iterator
 
 from django.test.utils import TestContextDecorator
 
@@ -9,3 +11,23 @@ def enable(self):
 
     def disable(self):
         logging.disable(logging.NOTSET)
+
+
+@contextmanager
+def ensure_logger_level(level: str = "INFO", name="openforms") -> Iterator[None]:
+    """
+    Set the (minimum) level for a given logger.
+
+    Base or individual settings may tweak the log level to reduce the overload for the
+    developer, but this affects tests that verify that log records are "written" by
+    application code for a certain log level.
+
+    This context manager allows you to pin the log level for a given text, irrespective
+    of individual preferences/developer settings.
+    """
+    logger = logging.getLogger(name)
+    original_level = logger.getEffectiveLevel()
+
+    logger.setLevel(logging._nameToLevel[level])
+    yield
+    logger.setLevel(original_level)