test

swebberuk · swebberuk · commit 36a5626f0679 · 2026-03-12T17:16:15.000Z
diff --git a/manage_breast_screening/config/settings.py b/manage_breast_screening/config/settings.py
@@ -284,6 +284,9 @@ def list_env(key):
         "correlation_id": {
             "()": "manage_breast_screening.core.middleware.exception_logging.CorrelationIdFilter",
         },
+        "suppress_handled_500s": {
+            "()": "manage_breast_screening.core.middleware.exception_logging.SuppressHandled500s",
+        },
     },
     "formatters": {
         "verbose": {
@@ -312,8 +315,9 @@ def list_env(key):
         },
         "django.request": {
             "handlers": ["console"],
-            "level": "CRITICAL",  # suppresses 4xx/5xx; middleware handles exceptions
+            "level": "INFO",
             "propagate": False,
+            "filters": ["suppress_handled_500s"],
         },
         "django.db.backends": {
             "level": "DEBUG" if LOG_QUERIES else "INFO",
diff --git a/manage_breast_screening/core/middleware/exception_logging.py b/manage_breast_screening/core/middleware/exception_logging.py
@@ -4,6 +4,7 @@
 from contextvars import ContextVar
 
 from django.utils.deprecation import MiddlewareMixin
+from opentelemetry import trace as otel_trace
 
 from manage_breast_screening.core.services.application_insights_logging import (
     ApplicationInsightsLogging,
@@ -21,26 +22,41 @@ def process_exception(self, request, exception):
             if user and hasattr(user, "is_authenticated") and user.is_authenticated
             else "Anonymous"
         )
-        context = (
-            f"URL: {request.path}, "
-            f"Method: {request.method}, "
-            f"User: {user_repr}, "
-            f"Exception: {exception}"
-        )
+
         correlation_id = getattr(request, "correlation_id", None)
 
         extra = {
             "url": request.path,
             "method": request.method,
             "user": user_repr,
-            "exception_type": type(exception).__name__,
             "correlation_id": correlation_id,
+            "exception_type": type(exception).__name__,
         }
-        app_insights_logger.exception(context, extra=extra)
+        extra_str = ", ".join(f"{k}={v}" for k, v in extra.items())
+        app_insights_logger.exception(f"{extra_str} {exception}", extra=extra)
+
+        request._exception_logged = True
 
         return None
 
 
+class SuppressHandled500s:
+    """
+    Django's `django.request` logger logs every unhandled view exception at `ERROR` level
+    automatically. `ExceptionLoggingMiddleware.process_exception` then logs the same exception
+    again. Both reach Application Insights, creating duplicates in the `exceptions` / `traces`
+    tables and inflating alert counts.
+    """
+
+    def filter(self, record):
+        request = getattr(record, "request", None)
+
+        if request and getattr(request, "_exception_logged", False):
+            return False
+
+        return True
+
+
 class CorrelationIdMiddleware(MiddlewareMixin):
     RESPONSE_HEADER = "X-Correlation-ID"
     CORRELATION_ID_HEADER = "HTTP_" + RESPONSE_HEADER.upper().replace("-", "_")
@@ -49,15 +65,26 @@ class CorrelationIdMiddleware(MiddlewareMixin):
     SAFE_ID_REGEX = re.compile(r"^[A-Za-z0-9._-]{1,64}$")
 
     def process_request(self, request):
+        correlation_id = self.find_correlation_id(request)
+        request.correlation_id = correlation_id
+        request._correlation_id_token = correlation_id_ctx.set(correlation_id)
+
+    def find_correlation_id(self, request):
+        """
+        Use correlation ID from incoming request headers if exists and is safe, otherwise use OTel trace ID if available, otherwise generate a new UUID.
+        """
+
         raw_id = request.META.get(self.CORRELATION_ID_HEADER)
         if raw_id and self.SAFE_ID_REGEX.match(raw_id):
-            correlation_id = raw_id
-        else:
-            correlation_id = str(uuid.uuid4())
-        request.correlation_id = correlation_id
+            return raw_id
 
-        # Store the token so we can reset later
-        request._correlation_id_token = correlation_id_ctx.set(correlation_id)
+        span = otel_trace.get_current_span()
+        ctx = span.get_span_context()
+        if ctx.is_valid:
+            # Use OTel trace ID — this links to all other App Insights telemetry
+            return format(ctx.trace_id, "032x")
+
+        return str(uuid.uuid4())
 
     def process_response(self, request, response):
         correlation_id = getattr(request, "correlation_id", None)
@@ -82,5 +109,4 @@ def process_exception(self, request, exception):
 class CorrelationIdFilter(logging.Filter):
     def filter(self, record):
         record.correlation_id = correlation_id_ctx.get() or "-"
-
         return True
diff --git a/manage_breast_screening/core/services/application_insights_logging.py b/manage_breast_screening/core/services/application_insights_logging.py
@@ -11,6 +11,7 @@ def __init__(self) -> None:
         self.logger_name = os.getenv(
             "APPLICATIONINSIGHTS_LOGGER_NAME", "manage-breast-screening"
         )
+        os.environ.setdefault("OTEL_SERVICE_NAME", self.logger_name)
         self.logger = self.getLogger()
 
     def configure_azure_monitor(self):
@@ -31,18 +32,27 @@ def getLogger(self):
         return logging.getLogger(self.logger_name)
 
     def exception(self, exception_name: str, extra: dict = None):
+        # Keys in extra are forwarded to Application Insights
+        # as customDimensions and become filterable in the Logs blade and alerting rules.
+        # stack_info=True is redundant with logger.exception()
         self.logger.exception(exception_name, stack_info=False, extra=extra)
 
+    # can remove once notifications app is removed
     def custom_event_warning(self, message: str, event_name: str):
-        extra = {
-            "microsoft.custom_event.name": event_name,
-            "additional_attrs": message,
-        }
-        self.logger.warning(message, extra=extra)
+        self.logger.warning(
+            message,
+            extra={
+                "microsoft.custom_event.name": event_name,
+                "additional_attrs": message,
+            },
+        )
 
+    # can remove once notifications app is removed
     def custom_event_info(self, message: str, event_name: str):
-        extra = {
-            "microsoft.custom_event.name": event_name,
-            "additional_attrs": message,
-        }
-        self.logger.info(message, extra=extra)
+        self.logger.info(
+            message,
+            extra={
+                "microsoft.custom_event.name": event_name,
+                "additional_attrs": message,
+            },
+        )
diff --git a/manage_breast_screening/core/tests/middleware/test_exception_logging.py b/manage_breast_screening/core/tests/middleware/test_exception_logging.py
@@ -54,11 +54,15 @@ def test_process_exception_logs_with_authenticated_user(
 
         middleware.process_exception(request, exception)
 
-        expected_context = (
-            "URL: /test/, Method: GET, User: testuser, Exception: Something went wrong"
-        )
         mock_logger.exception.assert_called_once_with(
-            expected_context, correlation_id="corr-id-123"
+            "url=/test/, method=GET, user=testuser, correlation_id=corr-id-123, exception_type=Exception Something went wrong",
+            extra={
+                "url": "/test/",
+                "method": "GET",
+                "user": "testuser",
+                "correlation_id": "corr-id-123",
+                "exception_type": "Exception",
+            },
         )
 
     def test_process_exception_logs_with_anonymous_user(self, monkeypatch, middleware):
@@ -74,11 +78,15 @@ def test_process_exception_logs_with_anonymous_user(self, monkeypatch, middlewar
 
         middleware.process_exception(request, exception)
 
-        expected_context = (
-            "URL: /test/, Method: GET, User: Anonymous, Exception: Details of exception"
-        )
         mock_logger.exception.assert_called_once_with(
-            expected_context, correlation_id=None
+            "url=/test/, method=GET, user=Anonymous, correlation_id=None, exception_type=Exception Details of exception",
+            extra={
+                "url": "/test/",
+                "method": "GET",
+                "user": "Anonymous",
+                "correlation_id": None,
+                "exception_type": "Exception",
+            },
         )
 
     def test_process_exception_logs_with_no_user(self, monkeypatch, middleware):
@@ -93,9 +101,15 @@ def test_process_exception_logs_with_no_user(self, monkeypatch, middleware):
 
         middleware.process_exception(request, exception)
 
-        expected_context = "URL: /test/, Method: GET, User: Anonymous, Exception: Fail"
         mock_logger.exception.assert_called_once_with(
-            expected_context, correlation_id="abc"
+            "url=/test/, method=GET, user=Anonymous, correlation_id=abc, exception_type=Exception Fail",
+            extra={
+                "url": "/test/",
+                "method": "GET",
+                "user": "Anonymous",
+                "correlation_id": "abc",
+                "exception_type": "Exception",
+            },
         )
 
     def test_process_exception_returns_none(self, middleware):
@@ -142,11 +156,15 @@ def test_process_exception_logs_correct_path_and_method(
 
         middleware.process_exception(request, exception)
 
-        expected_context = (
-            f"URL: {path}, Method: {method}, User: testuser, Exception: err"
-        )
         mock_logger.exception.assert_called_once_with(
-            expected_context, correlation_id="x"
+            f"url={path}, method={method}, user=testuser, correlation_id=x, exception_type=Exception err",
+            extra={
+                "url": path,
+                "method": method,
+                "user": "testuser",
+                "correlation_id": "x",
+                "exception_type": "Exception",
+            },
         )
 
 
@@ -298,15 +316,6 @@ def test_correlation_id_filter_uses_correlation_id_from_context(self, filter):
         assert filter.filter(record)
         assert record.correlation_id == test_correlation_id
 
-    def test_correlation_id_filter_preserves_existing_correlation_id(self, filter):
-        correlation_id_ctx.set("context-correlation-id-123")
-
-        record = self._make_record()
-        record.correlation_id = "record-correlation-id-123"
-
-        assert filter.filter(record)
-        assert record.correlation_id == "record-correlation-id-123"
-
     def test_correlation_id_filter_uses_default_when_not_set(self, filter):
         correlation_id_ctx.set(None)
 
diff --git a/manage_breast_screening/core/tests/services/test_application_insights_logging.py b/manage_breast_screening/core/tests/services/test_application_insights_logging.py
@@ -58,16 +58,7 @@ def test_raise_exception(self, mock_logging, mock_configure_azure):
         ApplicationInsightsLogging().exception("CustomError")
         mock_logging.getLogger.assert_called_with("insights-logger")
         mock_logging.getLogger.return_value.exception.assert_called_with(
-            "CustomError", stack_info=True, extra={}
-        )
-
-    def test_raise_exception_with_correlation_id(
-        self, mock_logging, mock_configure_azure
-    ):
-        ApplicationInsightsLogging().exception("CustomError", correlation_id="12345")
-        mock_logging.getLogger.assert_called_with("insights-logger")
-        mock_logging.getLogger.return_value.exception.assert_called_with(
-            "CustomError", stack_info=True, extra={"correlation_id": "12345"}
+            "CustomError", stack_info=False, extra=None
         )
 
     def test_custom_event_warning(self, mock_logging, mock_configure_azure):
@@ -83,22 +74,6 @@ def test_custom_event_warning(self, mock_logging, mock_configure_azure):
             },
         )
 
-    def test_custom_event_warning_with_correlation_id(
-        self, mock_logging, mock_configure_azure
-    ):
-        ApplicationInsightsLogging().custom_event_warning(
-            "something went wrong", "custom-event", correlation_id="12345"
-        )
-        mock_logging.getLogger.assert_called_with("insights-logger")
-        mock_logging.getLogger.return_value.warning.assert_called_with(
-            "something went wrong",
-            extra={
-                "microsoft.custom_event.name": "custom-event",
-                "additional_attrs": "something went wrong",
-                "correlation_id": "12345",
-            },
-        )
-
     def test_custom_event_info(self, mock_logging, mock_configure_azure):
         ApplicationInsightsLogging().custom_event_info(
             "some information", "custom-event"
@@ -111,19 +86,3 @@ def test_custom_event_info(self, mock_logging, mock_configure_azure):
                 "additional_attrs": "some information",
             },
         )
-
-    def test_custom_event_info_with_correlation_id(
-        self, mock_logging, mock_configure_azure
-    ):
-        ApplicationInsightsLogging().custom_event_info(
-            "some information", "custom-event", correlation_id="12345"
-        )
-        mock_logging.getLogger.assert_called_with("insights-logger")
-        mock_logging.getLogger.return_value.info.assert_called_with(
-            "some information",
-            extra={
-                "microsoft.custom_event.name": "custom-event",
-                "additional_attrs": "some information",
-                "correlation_id": "12345",
-            },
-        )
