Prevent sensitive information from being logged (#65)

* Rearrange logging to prevent logging secrets
This change logs the body of the request after the view has run in order to allow django to mark sensitive post parameters and cause them to be replaced with astericts in the logs.  See https://docs.djangoproject.com/en/2.2/howto/error-reporting/#django.views.decorators.debug.sensitive_post_parameters for more info

* use chunked_to_max and cleanup a long line

* Fix failing unit tests

* simplify the logic and add a unit test to validate that the sensitive parameters are not logged

* Make changes based on feedback

request_logging/middleware.py

@@ -9,6 +9,7 @@
     # Django < 1.10
     from django.core.urlresolvers import resolve, Resolver404
 from django.utils.termcolors import colorize
+from django.views.debug import SafeExceptionReporterFilter
 
 DEFAULT_LOG_LEVEL = logging.DEBUG
 DEFAULT_HTTP_4XX_LOG_LEVEL = logging.ERROR
@@ -95,6 +96,7 @@ def __init__(self, get_response=None):
     def __call__(self, request):
         self.process_request( request )
         response = self.get_response( request )
+        self.process_body(request)
         self.process_response( request, response )
         return response
 
@@ -153,24 +155,33 @@ def _log_request(self, request):
         logging_context = self._get_logging_context(request, None)
         self.logger.log(logging.INFO, method_path, logging_context)
         self._log_request_headers(request, logging_context)
-        self._log_request_body(request, logging_context)
 
     def _log_request_headers(self, request, logging_context):
         headers = {k: v for k, v in request.META.items() if k.startswith('HTTP_')}
 
         if headers:
             self.logger.log(self.log_level, headers, logging_context)
 
-    def _log_request_body(self, request, logging_context):
-        if request.body:
-            content_type = request.META.get('CONTENT_TYPE', '')
-            is_multipart = content_type.startswith('multipart/form-data')
-            if is_multipart:
-                self.boundary = '--' + content_type[30:]  # First 30 characters are "multipart/form-data; boundary="
-            if is_multipart:
-                self._log_multipart(self._chunked_to_max(request.body), logging_context)
-            else:
-                self.logger.log(self.log_level, self._chunked_to_max(request.body), logging_context)
+    def process_body(self, request):
+        if not request.body:
+            return
+        should_skip_logging = self._should_log_route(request)
+        if should_skip_logging:
+            return
+        logging_context = self._get_logging_context(request, None)
+        content_type = request.META.get('CONTENT_TYPE', '')
+        is_multipart = content_type.startswith('multipart/form-data')
+        to_log = None
+        if is_multipart:
+            self.boundary = '--' + content_type[30:]  # First 30 characters are "multipart/form-data; boundary="
+            self._log_multipart(self._chunked_to_max(request.body), logging_context)
+        elif request.POST:
+            to_log = str(SafeExceptionReporterFilter().get_post_parameters(request).dict())
+        else:
+            to_log = request.body
+
+        if to_log:
+            self.logger.log(self.log_level, self._chunked_to_max(to_log), logging_context)
 
     def process_response(self, request, response):
         resp_log = "{} {} - {}".format(request.method, request.get_full_path(), response.status_code)

tests.py

@@ -8,7 +8,7 @@
 import sys
 from django.conf import settings
 from django.test import RequestFactory, override_settings
-from django.http import HttpResponse, StreamingHttpResponse
+from django.http import HttpResponse, StreamingHttpResponse, QueryDict
 
 import request_logging
 from request_logging.middleware import LoggingMiddleware, DEFAULT_LOG_LEVEL, DEFAULT_COLORIZE, DEFAULT_MAX_BODY_LENGTH,\
@@ -59,6 +59,7 @@ def test_no_exception_risen(self, mock_log):
         body = u"some body"
         request = self.factory.post("/a-missing-route-somewhere", data={"file": body})
         self.middleware.process_request(request)
+        self.middleware.process_body(request)
         self._assert_logged(mock_log, body)
 
 
@@ -79,13 +80,15 @@ def test_request_body_logged(self, mock_log):
         body = u"some body"
         request = self.factory.post("/somewhere", data={"file": body})
         self.middleware.process_request(request)
+        self.middleware.process_body(request)
         self._assert_logged(mock_log, body)
 
     def test_request_binary_logged(self, mock_log):
         body = u"some body"
         datafile = io.StringIO(body)
         request = self.factory.post("/somewhere", data={"file": datafile})
         self.middleware.process_request(request)
+        self.middleware.process_body(request)
         self._assert_logged(mock_log, "(binary data)")
 
     def test_request_jpeg_logged(self, mock_log):
@@ -96,6 +99,7 @@ def test_request_jpeg_logged(self, mock_log):
         datafile = io.BytesIO(body)
         request = self.factory.post("/somewhere", data={"file": datafile})
         self.middleware.process_request(request)
+        self.middleware.process_body(request)
         self._assert_logged(mock_log, "(multipart/form)")
 
     def test_request_headers_logged(self, mock_log):
@@ -315,7 +319,7 @@ def test_default_max_body_length(self, mock_log):
 
         body = DEFAULT_MAX_BODY_LENGTH * "0" + "1"
         request = factory.post("/somewhere", data={"file": body})
-        middleware.process_request(request)
+        middleware.process_body(request)
 
         request_body_str = request.body if isinstance(request.body, str) else request.body.decode()
         self._assert_logged(mock_log, re.sub(r'\r?\n', '', request_body_str[:DEFAULT_MAX_BODY_LENGTH]))
@@ -328,7 +332,7 @@ def test_customized_max_body_length(self, mock_log):
 
         body = 150 * "0" + "1"
         request = factory.post("/somewhere", data={"file": body})
-        middleware.process_request(request)
+        middleware.process_body(request)
 
         request_body_str = request.body if isinstance(request.body, str) else request.body.decode()
         self._assert_logged(mock_log, re.sub(r'\r?\n', '', request_body_str[:150]))
@@ -400,6 +404,31 @@ def test_still_logs_path(self, mock_log):
         self._assert_logged(mock_log, uri)
 
 
+@mock.patch.object(request_logging.middleware, "request_logger")
+class DjangoDecoratorTestCase(BaseLogTestCase):
+    def setUp(self):
+        self.factory = RequestFactory()
+        def get_response(request):
+            response = mock.MagicMock()
+            response.status_code = 200
+            response.get.return_value = 'application/json'
+            return response
+        self.middleware = LoggingMiddleware(get_response)
+
+    # Because django isn't actually processing this test this test stubbed
+    # out the important parts of what it does which is processes a decorator
+    # like @sensitive_post_parameters('pass__word'), which gets added
+    # to the request object, and then I also created the QueryDict that is
+    # the underlying POST data.
+    def test_log_sensitive_post_parameters(self, mock_log):
+        uri = "/dont_log_sensitive_parameter"
+        request = self.factory.post(uri)
+        request.POST = QueryDict('pass_word=foo')
+        request.sensitive_post_parameters = ["pass_word"]
+        self.middleware.__call__(request)
+        self._assert_not_logged(mock_log, "foo")
+
+
 @mock.patch.object(request_logging.middleware, "request_logger")
 class DRFTestCase(BaseLogTestCase):
     def setUp(self):