feat: add decorator that can be used to log incoming REST request data (

#2364)

[APER-3122]

Adds a decorator that can be used to log incoming REST request data. This will be used to get more visibility into the grade updates flowing from the LMS to Credentials.

This functionality will be gated using a WaffleSwitch so that we don't cause a massive spike in log size. This is intended to be used for debugging when needed.

credentials/apps/api/v2/decorators.py

@@ -0,0 +1,39 @@
+"""
+Decorators for the API app of Credentials.
+"""
+
+import logging
+
+from django.conf import settings
+
+
+logger = logging.getLogger(__name__)
+
+
+def log_incoming_request(func):
+    """
+    A decorator that can be used to log information from an incoming REST request. Please take care if using this
+    decorator, we don't want to accidentally log any secrets or sensitive PII.
+
+    Use of this decorator is also gated by the `LOG_INCOMING_REQUESTS` waffle switch. This is to ensure that we can
+    toggle this functionality as needed and keep log sizes reasonable.
+    """
+
+    def wrapper(*args, **kwargs):
+        if settings.LOG_INCOMING_REQUESTS.is_enabled():
+            try:
+                request = args[1]
+                data = request.body
+                logger.info(
+                    f"{request.method} request received to endpoint [{request.get_full_path()}] from user "
+                    f"[{request.user.username}] originating from [{request.META.get('HTTP_HOST', 'Unknown')}] "
+                    f"with data: [{data}]"
+                )
+            except Exception as exc:
+                # catch overly broad exception to try to ensure if logging doesn't work the request will still be
+                # processed
+                logger.error(f"Error logging incoming request: {exc}. Continuing...")
+
+        return func(*args, **kwargs)
+
+    return wrapper

credentials/apps/api/v2/tests/test_decorators.py

@@ -0,0 +1,79 @@
+"""
+Tests for the API app's `decorators.py` file.
+"""
+
+from django.conf import settings
+from django.http import HttpResponse
+from django.test import TestCase
+from django.test.client import RequestFactory
+from edx_toggles.toggles.testutils import override_waffle_switch
+from testfixtures import LogCapture
+
+from credentials.apps.api.v2.decorators import log_incoming_request
+from credentials.apps.core.tests.factories import UserFactory
+
+
+class CredentialsApiDecoratorTests(TestCase):
+    """
+    Unit tests for the API app's `decorators.py` file.
+    """
+
+    def setUp(self):
+        super().setUp()
+        self.request = RequestFactory().post("/api/v2/grades/")
+        self.user = UserFactory()
+        self.request.user = self.user
+
+    def _test_view(self, request, *args, **kwargs):
+        return HttpResponse("YOLO")
+
+    @override_waffle_switch(settings.LOG_INCOMING_REQUESTS, active=True)
+    def test_log_incoming_requests_decorator_waffle_enabled(self):
+        """
+        Test that ensures when a function decorated with the `log_incoming_requests` decorator, it emits the expected
+        log messages if the setting gating the functionality is enabled.
+        """
+        expected_msg = (
+            f"{self.request.method} request received to endpoint [{self.request.get_full_path()}] from user "
+            f"[{self.request.user.username}] originating from [Unknown] with data: [{self.request.body}]"
+        )
+        decorated_view = log_incoming_request(self._test_view)
+
+        args = (None, self.request)
+        kwargs = {}
+        with LogCapture() as log:
+            decorated_view(*args, **kwargs)
+
+        assert log.records[0].msg == expected_msg
+
+    @override_waffle_switch(settings.LOG_INCOMING_REQUESTS, active=False)
+    def test_log_incoming_requests_decorator_waffle_disabled(self):
+        """
+        Test that ensures when a function decorated with the `log_incoming_requests` decorator, it does not emit log
+        messges if the setting gating the functionality is disabled.
+        """
+        decorated_view = log_incoming_request(self._test_view)
+
+        args = (None, self.request)
+        kwargs = {}
+        with LogCapture() as log:
+            decorated_view(*args, **kwargs)
+
+        assert log.records == []
+
+    @override_waffle_switch(settings.LOG_INCOMING_REQUESTS, active=True)
+    def test_log_incoming_requests_decorator_with_exception(self):
+        """
+        Test that verifies an expected error message in our logs if an exception occurs when trying to log request data
+        while using the `log_incoming_requests` decorator.
+        """
+        expected_msg = "Error logging incoming request: 'NoneType' object has no attribute 'body'. Continuing..."
+
+        decorated_view = log_incoming_request(self._test_view)
+
+        with LogCapture() as log:
+            response = decorated_view(None, None)
+
+        assert log.records[0].msg == expected_msg
+        assert response.status_code == 200
+        assert response.content == b"YOLO"

credentials/apps/api/v2/tests/test_views.py

@@ -11,6 +11,7 @@
 from django.urls import reverse
 from rest_framework.renderers import JSONRenderer
 from rest_framework.test import APIRequestFactory, APITestCase
+from testfixtures import LogCapture
 from waffle.testutils import override_switch
 
 from credentials.apps.api.tests.mixins import JwtMixin
@@ -572,6 +573,37 @@ def test_create_with_existing_user_grade(self):
         self.assertEqual(grade.letter_grade, "B")
         self.assertDictEqual(response.data, self.serialize_user_grade(grade))
 
+    @ddt.data(True, False)
+    def test_create_with_logging_decorator_enabled(self, decorator_enabled):
+        """
+        A test that verifies expected log messages from Grade views decorated with the `log_incoming_requests`
+        decorator.
+        """
+        expected_log_decorator_enabled = (
+            f"POST request received to endpoint [/api/v2/grades/] from user [{self.user.username}] originating from "
+            f"[Unknown] with data: [{str.encode(json.dumps(self.data))}]"
+        )
+        formatted_grade = "{:.4f}".format(self.data["percent_grade"])
+        expected_logs = [
+            f"Updated grade for user [{self.data['username']}] in course [{self.data['course_run']}] with "
+            f"percent_grade [{formatted_grade}], letter_grade [{self.data['letter_grade']}], verified "
+            f"[{self.data['verified']}], and lms_last_updated_at [None]"
+        ]
+
+        if decorator_enabled:
+            expected_logs.append(expected_log_decorator_enabled)
+
+        self.authenticate_user(self.user)
+        self.add_user_permission(self.user, "add_usergrade")
+
+        with override_switch("api.log_incoming_requests", active=decorator_enabled):
+            with LogCapture() as log:
+                self.client.post(self.list_path, data=json.dumps(self.data), content_type=JSON_CONTENT_TYPE)
+
+        log_messages = [log.msg for log in log.records]
+        for log in expected_logs:
+            assert log in log_messages
+
     @ddt.data("put", "patch")
     def test_update(self, method):
         """Verify the endpoint supports updating the status of a UserGrade, but no other fields."""

credentials/apps/api/v2/views.py

@@ -10,6 +10,7 @@
 from rest_framework.throttling import ScopedRateThrottle
 from rest_framework.views import APIView, exception_handler
 
+from credentials.apps.api.v2.decorators import log_incoming_request
 from credentials.apps.api.v2.filters import UserCredentialFilter
 from credentials.apps.api.v2.permissions import CanReplaceUsername, UserCredentialPermissions
 from credentials.apps.api.v2.serializers import (
@@ -146,15 +147,18 @@ class GradeViewSet(mixins.CreateModelMixin, mixins.UpdateModelMixin, viewsets.Ge
     throttle_scope = "grade_view"
     queryset = UserGrade.objects.all()
 
-    def create(self, request, *args, **kwargs):  # pylint: disable=useless-super-delegation
+    @log_incoming_request
+    def create(self, request, *args, **kwargs):
         """Create a new grade."""
         return super().create(request, *args, **kwargs)
 
-    def partial_update(self, request, *args, **kwargs):  # pylint: disable=useless-super-delegation
+    @log_incoming_request
+    def partial_update(self, request, *args, **kwargs):
         """Update a grade."""
         return super().partial_update(request, *args, **kwargs)
 
-    def update(self, request, *args, **kwargs):  # pylint: disable=useless-super-delegation
+    @log_incoming_request
+    def update(self, request, *args, **kwargs):
         """Update a grade."""
         return super().update(request, *args, **kwargs)
 

credentials/settings/base.py

@@ -584,3 +584,12 @@
         },
     },
 }
+
+# .. toggle_name: LOG_INCOMING_REQUESTS
+# .. toggle_implementation: WaffleSwitch
+# .. toggle_default: False
+# .. toggle_description: Toggle to control whether we log incoming REST requests through the use of the
+#   `log_incoming_requests` decorator.
+# .. toggle_use_cases: opt_in
+# .. toggle_creation_date: 2024-01-25
+LOG_INCOMING_REQUESTS = WaffleSwitch("api.log_incoming_requests", module_name=__name__)