#3251 - Prepend user info for logs [AD]

src/registrar/config/settings.py

@@ -27,6 +27,7 @@
 import logging
 import traceback
 from django.utils.log import ServerFormatter
+from ..thread_locals import get_log_user_email, get_log_ip, get_request_path
 
 # # #                          ###
 #      Setup code goes here      #
@@ -203,8 +204,8 @@
     "registrar.registrar_middleware.CheckPortfolioMiddleware",
     # Restrict access using Opt-Out approach
     "registrar.registrar_middleware.RestrictAccessMiddleware",
-    # Our own router logs that included user info to speed up log tracing time on stable
-    "registrar.registrar_middleware.RequestLoggingMiddleware",
+    # Add User Info to Console logs
+    "registrar.registrar_middleware.RegisterLoggingMiddleware",
 ]
 
 # application object used by Django's built-in servers (e.g. `runserver`)
@@ -494,10 +495,32 @@ def format(self, record):
         if not hasattr(record, "server_time"):
             record.server_time = self.formatTime(record, self.datefmt)
 
-        log_entry = {"server_time": record.server_time, "level": record.levelname, "message": formatted_record}
+        log_entry = {
+            "server_time": record.server_time,
+            "level": record.levelname,
+            "message": formatted_record,
+        }
         return json.dumps(log_entry)
 
 
+class UserFormatter(logging.Formatter):
+    def format(self, record):
+        record.user_email = get_log_user_email()
+        record.ip = get_log_ip()
+        record.request_path = get_request_path()
+        parts = []
+        if record.user_email:
+            parts.append(f"user: {record.user_email}")
+        if record.ip:
+            parts.append(f"ip: {record.ip}")
+        if record.request_path:
+            parts.append(f"request_path: {record.request_path}")
+
+        prefix = " | ".join(parts)
+        msg = super().format(record)
+        return f"{prefix} | {msg}" if prefix else msg
+
+
 # If we're running locally we don't want json formatting
 if "localhost" in env_base_url:
     django_handlers = ["console"]
@@ -522,12 +545,17 @@ def format(self, record):
             "format": "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",
             "datefmt": "%d/%b/%Y %H:%M:%S",
         },
+        "user_verbose": {
+            "()": UserFormatter,
+            "format": "[%(asctime)s] %(levelname)s [%(name)s:%(lineno)s] %(message)s",
+            "datefmt": "%d/%b/%Y %H:%M:%S",
+        },
         "simple": {
             "format": "%(levelname)s %(message)s",
         },
         "django.server": {
             "()": "django.utils.log.ServerFormatter",
-            "format": "[{server_time}] {message}",
+            "format": "%(emails)s | %(ip)s | [{server_time}] {message}",
             "style": "{",
         },
         "json.server": {
@@ -543,13 +571,13 @@ def format(self, record):
         "console": {
             "level": env_log_level,
             "class": "logging.StreamHandler",
-            "formatter": "verbose",
+            "formatter": "user_verbose",
         },
         # Special handlers for split logging case
         "split_console": {
             "level": env_log_level,
             "class": "logging.StreamHandler",
-            "formatter": "verbose",
+            "formatter": "user_verbose",
             "filters": ["below_error"],
         },
         "split_json": {
@@ -575,7 +603,7 @@ def format(self, record):
         "below_error": {
             "()": "django.utils.log.CallbackFilter",
             "callback": lambda record: record.levelno < logging.ERROR,
-        }
+        },
     },
     # define loggers: these are "sinks" into which
     # messages are sent for processing

src/registrar/models/portfolio.py

@@ -138,7 +138,6 @@ def save(self, *args, **kwargs):
         super().save(*args, **kwargs)
 
     def clean(self):
-
         # Checks if federal agency already exists in the portfolio table
         if (
             self.federal_agency != FederalAgency.get_non_federal_agency()

src/registrar/registrar_middleware.py

@@ -14,6 +14,7 @@
 from waffle.decorators import flag_is_active
 
 from registrar.models.utility.generic_helper import replace_url_queryparams
+from .thread_locals import set_log_user
 
 logger = logging.getLogger(__name__)
 
@@ -224,29 +225,25 @@ def __call__(self, request):
         return self.get_response(request)
 
 
-class RequestLoggingMiddleware:
+class RegisterLoggingMiddleware:
     """
-    Middleware to log user email, remote address, and request path.
+    Middleware to log user email, remote address, and request path to prepend to logs.
     """
 
     def __init__(self, get_response):
         self.get_response = get_response
 
     def __call__(self, request):
-        response = self.get_response(request)
-
-        # Only log in production (stable)
-        if getattr(settings, "IS_PRODUCTION", False):
-            # Get user email (if authenticated), else "Anonymous"
-            user_email = request.user.email if request.user.is_authenticated else "Anonymous"
-
-            # Get remote IP address
-            remote_ip = request.META.get("REMOTE_ADDR", "Unknown IP")
-
-            # Get request path
-            request_path = request.path
-
-            # Log user information
-            logger.info(f"Router log | User: {user_email} | IP: {remote_ip} | Path: {request_path}")
-
-        return response
+        # Get user email (if authenticated), else "Anonymous"
+        # if getattr(settings, "IS_PRODUCTION", False):
+        user_email = request.user.email if request.user.is_authenticated else "Anonymous"
+        # Get remote IP address
+        remote_ip = request.META.get("REMOTE_ADDR", "Unknown IP")
+        # Get request path
+        request_path = request.path
+
+        # set thread locals
+        set_log_user(user_email, remote_ip, request_path)
+        # Log user information
+        logger.info(f"Router log | User: {user_email} | IP: {remote_ip} | Path: {request_path}")
+        return self.get_response(request)

src/registrar/tests/test_middleware_logging.py

@@ -1,48 +1,66 @@
-from django.test import TestCase, RequestFactory, override_settings
-from unittest.mock import patch, MagicMock
-from django.contrib.auth.models import AnonymousUser, User
+from django.test import TestCase
+from registrar.config.settings import UserFormatter
+from django.urls import reverse
+from django.contrib.auth.models import AnonymousUser
+from unittest.mock import patch
 
-from registrar.registrar_middleware import RequestLoggingMiddleware
+import io
+import logging
 
+from django.contrib.auth import get_user_model
+from ..thread_locals import _user_local
 
-class RequestLoggingMiddlewareTest(TestCase):
+def clear_threadlocal():
+    for attr in ["ip", "user_email", "request_path"]:
+        if hasattr(_user_local, attr):
+            delattr(_user_local, attr)
+
+class RegisterLoggingMiddlewareTest(TestCase):
     """Test 'our' middleware logging."""
 
     def setUp(self):
-        self.factory = RequestFactory()
-        self.get_response_mock = MagicMock()
-        self.middleware = RequestLoggingMiddleware(self.get_response_mock)
-
-    @override_settings(IS_PRODUCTION=True)  # Scopes change to this test only
-    @patch("logging.Logger.info")
-    def test_logging_enabled_in_production(self, mock_logger):
-        """Test that logging occurs when IS_PRODUCTION is True"""
-        request = self.factory.get("/test-path", **{"REMOTE_ADDR": "Unknown IP"})  # Override IP
-        request.user = User(username="testuser", email="[email protected]")
+        clear_threadlocal()
+        self.stream = io.StringIO()
+        self.handler = logging.StreamHandler(self.stream)
+        self.handler.setFormatter(UserFormatter("%(message)s"))
+        self.logger = logging.getLogger(__name__)
+        self.logger.addHandler(self.handler)
+        self.logger.setLevel(logging.INFO)
 
-        self.middleware(request)  # Call middleware
+    def tearDown(self):
+        self.logger.removeHandler(self.handler)
+        clear_threadlocal()
+        self.handler.close()
+
+
+    def test_no_user_info(self):
+        self.client.get(reverse("domains"))
 
-        mock_logger.assert_called_once_with(
-            "Router log | User: [email protected] | IP: Unknown IP | Path: /test-path"
-        )
+        self.logger.info("Anonymous Test")
 
-    @patch("logging.Logger.info")
-    def test_logging_disabled_in_non_production(self, mock_logger):
-        """Test that logging does not occur when IS_PRODUCTION is False"""
-        request = self.factory.get("/test-path")
-        request.user = User(username="testuser", email="[email protected]")
+        self.handler.flush()
 
-        self.middleware(request)  # Call middleware
+        output = self.stream.getvalue()
 
-        mock_logger.assert_not_called()  # Ensure no logs are generated
+        self.assertNotIn("user", output)
+
 
-    @override_settings(IS_PRODUCTION=True)  # Scopes change to this test only
-    @patch("logging.Logger.info")
-    def test_logging_anonymous_user(self, mock_logger):
-        """Test logging for an anonymous user"""
-        request = self.factory.get("/anonymous-path", **{"REMOTE_ADDR": "Unknown IP"})  # Override IP
-        request.user = AnonymousUser()  # Simulate an anonymous user
+    def test_middleware_sets_user_email(self):
+        user = get_user_model().objects.create_user(
+            username="test",
+            first_name="test",
+            email="[email protected]",
+            phone="8002224444",
+        )
+        self.client.force_login(user)
+        self.client.get(reverse("domains"))
 
-        self.middleware(request)  # Call middleware
+        # adding log info to test
 
-        mock_logger.assert_called_once_with("Router log | User: Anonymous | IP: Unknown IP | Path: /anonymous-path")
+        self.logger.info("Testing middleware")
+        self.handler.flush()
+        log_output = self.stream.getvalue()
+        self.client.logout()
+        self.assertIn(user.email, log_output)
+        self.assertIn("Testing middleware", log_output)
+

src/registrar/thread_locals.py

@@ -0,0 +1,21 @@
+import threading
+
+_user_local = threading.local()
+
+
+def set_log_user(user_email, ip, request_path):
+    _user_local.user_email = user_email
+    _user_local.ip = ip
+    _user_local.request_path = request_path
+
+
+def get_log_user_email():
+    return getattr(_user_local, "user_email", None)
+
+
+def get_log_ip():
+    return getattr(_user_local, "ip", None)
+
+
+def get_request_path():
+    return getattr(_user_local, "request_path", None)

src/registrar/views/domain.py

@@ -1209,6 +1209,7 @@ class DomainUsersView(DomainBaseView):
 
     def get_context_data(self, **kwargs):
         """The initial value for the form (which is a formset here)."""
+        logger.info("inside the domain users view")
         context = super().get_context_data(**kwargs)
 
         # Get portfolio from session (if set)
@@ -1417,6 +1418,7 @@ class DomainDeleteUserView(DeleteView):
 
     def get_object(self, queryset=None):
         """Custom get_object definition to grab a UserDomainRole object from a domain_id and user_id"""
+        logger.info("deleted domain")
         domain_id = self.kwargs.get("domain_pk")
         user_id = self.kwargs.get("user_pk")
         return UserDomainRole.objects.get(domain=domain_id, user=user_id)