Add the ability to opt into logging on a per-endpoint basis

README.md

@@ -55,6 +55,10 @@ See `REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL` setting to override this.
 
 A `no_logging` decorator is included for views with sensitive data.
 
+An `opt_into_logging` decorator is included to always log requests + response for a view regardless of what's returned for `REQUEST_LOGGING_OPT_IN_CONDITIONAL` or `RESPONSE_LOGGING_OPT_IN_CONDITIONAL`.
+
+**Note:** attempting to wrap a method in both `no_logging` and `opt_into_logging` will raise an exception.
+
 By default, value of Http headers `HTTP_AUTHORIZATION` and `HTTP_PROXY_AUTHORIZATION` are replaced wih `*****`. You can use `REQUEST_LOGGING_SENSITIVE_HEADERS` setting to override this default behaviour with your list of sensitive headers.
 
 ## Django settings
@@ -74,12 +78,33 @@ If you set `REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL=logging.INFO` they will be logged
 ### REQUEST_LOGGING_SENSITIVE_HEADERS
 The value of the headers defined in this settings will be replaced with `'*****'` to hide the sensitive information while logging. E.g. `REQUEST_LOGGING_SENSITIVE_HEADERS = ['HTTP_AUTHORIZATION', 'HTTP_USER_AGENT']`
 
+### REQUEST_LOGGING_OPT_IN_CONDITIONAL
+A function called with the `request` object. Should return a boolean, for example, to turn off all logging for all requests:
+
+```python
+REQUEST_LOGGING_OPT_IN_CONDITIONAL = lambda request: False
+```
+
+Or to log only requests on the path `/my/path`:
+
+```python
+REQUEST_LOGGING_OPT_IN_CONDITIONAL = lambda request: request.get_full_path() == "/my/path"
+```
+
+### RESPONSE_LOGGING_OPT_IN_CONDITIONAL
+A function called with the `request` object. Should return a boolean, for example, to only log a response with a status code above 400:
+
+```python
+RESPONSE_LOGGING_OPT_IN_CONDITIONAL = lambda response: response.status_code > 400
+```
+
+
 
 ## Deploying, Etc.
 
 ### Maintenance
 
-Use `pyenv` to maintain a set of virtualenvs for 2.7 and a couple versions of Python 3. 
+Use `pyenv` to maintain a set of virtualenvs for 2.7 and a couple versions of Python 3.
 Make sure the `requirements-dev.txt` installs for all of them, at least until we give up on 2.7.
 At that point, update this README to let users know the last version they can use with 2.7.
 
@@ -93,17 +118,17 @@ At that point, update this README to let users know the last version they can us
     index-servers=
         testpypi
         pypi
-    
+
     [testpypi]
     username = rhumbix
     password = password for [email protected] at Pypi
-    
+
     [pypi]
     username = rhumbix
     password = password for [email protected] at Pypi
 ```
 
-### Publishing  
+### Publishing
 
 - Bump the version value in `request_logging/__init__.py`
 - Run `python setup.py publish`

request_logging/decorators.py

@@ -1,10 +1,37 @@
 from functools import wraps
-from .middleware import NO_LOGGING_ATTR, NO_LOGGING_MSG_ATTR, NO_LOGGING_MSG
+from .middleware import (
+    NO_LOGGING_FUNCS,
+    OPT_INTO_LOGGING_FUNCS,
+    NO_LOGGING_MSG,
+)
 
 
-def no_logging(msg=None, silent=False):
-    def wrapper(func):
-        setattr(func, NO_LOGGING_ATTR, True)
-        setattr(func, NO_LOGGING_MSG_ATTR, (msg if msg else NO_LOGGING_MSG) if not silent else None)
+class DjangoRequestsCollidingDecorators(Exception):
+    pass
+
+
+def no_logging(msg=None, silent=False): # type: (str, bool) -> Callable[..., Any]
+    def wrapper(func): # type: Callable[..., Any]
+        if not silent:
+            no_logging_message = msg if msg else NO_LOGGING_MSG
+        else:
+            no_logging_message = None
+
+        NO_LOGGING_FUNCS[func] = no_logging_message
+
+        if func in OPT_INTO_LOGGING_FUNCS:
+            raise DjangoRequestsCollidingDecorators
+
         return func
+
     return wrapper
+
+
+def opt_into_logging(func):  # type: (Callable[..., Any]) -> Callable[..., Any]
+    # No need to ensure decorators do not collide, it happens within each
+    # conditional annotation method
+    OPT_INTO_LOGGING_FUNCS.add(func)
+    if func in NO_LOGGING_FUNCS:
+        raise DjangoRequestsCollidingDecorators
+
+    return func

request_logging/middleware.py

@@ -1,7 +1,9 @@
+from collections import namedtuple
 import logging
 import re
 
 from django.conf import settings
+
 try:
     # Django >= 1.10
     from django.urls import resolve, Resolver404
@@ -10,6 +12,17 @@
     from django.core.urlresolvers import resolve, Resolver404
 from django.utils.termcolors import colorize
 
+
+def _true(*args, **kwargs):
+    # type: (Any, Any) -> bool
+    """Logging opt-in default, always log all the things!"""
+    return True
+
+
+# Avoid potential typos (I am bad at speeling)
+REQUEST = 'REQUEST'
+RESPONSE = 'RESPONSE'
+
 DEFAULT_LOG_LEVEL = logging.DEBUG
 DEFAULT_HTTP_4XX_LOG_LEVEL = logging.ERROR
 DEFAULT_COLORIZE = True
@@ -22,14 +35,21 @@
     'colorize': 'REQUEST_LOGGING_ENABLE_COLORIZE',
     'max_body_length': 'REQUEST_LOGGING_MAX_BODY_LENGTH',
     'sensitive_headers': 'REQUEST_LOGGING_SENSITIVE_HEADERS',
+    'logging_opt_in': {
+        REQUEST: 'REQUEST_LOGGING_OPT_IN_CONDITIONAL',
+        RESPONSE: 'RESPONSE_LOGGING_OPT_IN_CONDITIONAL',
+    }
 }
 BINARY_REGEX = re.compile(r'(.+Content-Type:.*?)(\S+)/(\S+)(?:\r\n)*(.+)', re.S | re.I)
 BINARY_TYPES = ('image', 'application')
-NO_LOGGING_ATTR = 'no_logging'
-NO_LOGGING_MSG_ATTR = 'no_logging_msg'
 NO_LOGGING_MSG = 'No logging for this endpoint'
 request_logger = logging.getLogger('django.request')
 
+NO_LOGGING_FUNCS = {} # type: Dict[Callable[..., Any], Optional[str]]
+OPT_INTO_LOGGING_FUNCS = set() # type: Set[Callable[..., Any]]
+
+ShouldLogRoute = namedtuple("ShouldLogRoute", ["log_route", "skip_reason"])
+
 
 class Logger:
     def log(self, level, msg, logging_context):
@@ -70,6 +90,11 @@ def __init__(self, get_response=None):
         self.log_level = getattr(settings, SETTING_NAMES['log_level'], DEFAULT_LOG_LEVEL)
         self.http_4xx_log_level = getattr(settings, SETTING_NAMES['http_4xx_log_level'], DEFAULT_HTTP_4XX_LOG_LEVEL)
         self.sensitive_headers = getattr(settings, SETTING_NAMES['sensitive_headers'], DEFAULT_SENSITIVE_HEADERS)
+        self.logging_opt_in_defaults = {
+            REQUEST: getattr(settings, SETTING_NAMES['logging_opt_in'][REQUEST], _true),
+            RESPONSE: getattr(settings, SETTING_NAMES['logging_opt_in'][RESPONSE], _true),
+        }
+
         if not isinstance(self.sensitive_headers, list):
             raise ValueError(
                 "{} should be list. {} is not list.".format(SETTING_NAMES['sensitive_headers'], self.sensitive_headers)
@@ -107,14 +132,14 @@ def __call__(self, request):
         return response
 
     def process_request(self, request):
-        skip_logging, because = self._should_log_route(request)
-        if skip_logging:
-            if because is not None:
-                return self._skip_logging_request(request, because)
+        should_log_route = self._should_log_route(request)
+        if not should_log_route.log_route:
+            if should_log_route.skip_reason is not None:
+                return self._skip_logging_request(request, should_log_route.skip_reason)
         else:
             return self._log_request(request)
 
-    def _should_log_route(self, request):
+    def _get_api_func(self, request):
         # request.urlconf may be set by middleware or application level code.
         # Use this urlconf if present or default to None.
         # https://docs.djangoproject.com/en/2.1/topics/http/urls/#how-django-processes-a-request
@@ -141,9 +166,18 @@ def _should_log_route(self, request):
         elif hasattr(view, 'view_class'):
             # This is for django class-based views
             func = getattr(view.view_class, method, None)
-        no_logging = getattr(func, NO_LOGGING_ATTR, False)
-        no_logging_msg = getattr(func, NO_LOGGING_MSG_ATTR, None)
-        return no_logging, no_logging_msg
+
+        return func
+
+    def _should_log_route(self, request):
+        func = self._get_api_func(request)
+        if func in OPT_INTO_LOGGING_FUNCS:
+            return ShouldLogRoute(log_route=True, skip_reason=None)
+
+        if func in NO_LOGGING_FUNCS:
+            return ShouldLogRoute(log_route=False, skip_reason=NO_LOGGING_FUNCS.get(func, None))
+
+        return ShouldLogRoute(log_route=self.logging_opt_in_defaults[REQUEST](request), skip_reason=None)
 
     def _skip_logging_request(self, request, reason):
         method_path = "{} {}".format(request.method, request.get_full_path())
@@ -184,28 +218,35 @@ def _log_request_body(self, request, logging_context):
 
     def process_response(self, request, response):
         resp_log = "{} {} - {}".format(request.method, request.get_full_path(), response.status_code)
-        skip_logging, because = self._should_log_route(request)
-        if skip_logging:
-            if because is not None:
-                self.logger.log_error(logging.INFO, resp_log, {'args': {}, 'kwargs': { 'extra' :  { 'no_logging': because } }})
-            return response
-        logging_context = self._get_logging_context(request, response)
+        api_func = self._get_api_func(request)
 
-        if response.status_code in range(400, 500):
-            if self.http_4xx_log_level == DEFAULT_HTTP_4XX_LOG_LEVEL:
-                # default, log as per 5xx
+        should_log_route = self._should_log_route(request)
+        should_log_response = self.logging_opt_in_defaults[RESPONSE](response) or api_func in OPT_INTO_LOGGING_FUNCS
+        if not should_log_route.log_route:
+            if should_log_route.skip_reason is not None:
+                self.logger.log_error(logging.INFO, resp_log, {'args': {}, 'kwargs': { 'extra' :  { 'no_logging': should_log_route.skip_reason } }})
+
+            if not should_log_response:
+                return response
+
+        logging_context = self._get_logging_context(request, response)
+        if should_log_response:
+            # Either the response is opted-in to logging by default or we've
+            # conditionally selected the response to be logged. Regardless, log it!
+            if 400 <= response.status_code < 500:
+                if self.http_4xx_log_level == DEFAULT_HTTP_4XX_LOG_LEVEL:
+                    # default, log as per 5xx
+                    self.logger.log_error(logging.INFO, resp_log, logging_context)
+                    self._log_resp(logging.ERROR, response, logging_context)
+                else:
+                    self.logger.log(self.http_4xx_log_level, resp_log, logging_context)
+                    self._log_resp(self.log_level, response, logging_context)
+            elif 500 <= response.status_code < 600:
                 self.logger.log_error(logging.INFO, resp_log, logging_context)
                 self._log_resp(logging.ERROR, response, logging_context)
             else:
-                self.logger.log(self.http_4xx_log_level, resp_log, logging_context)
+                self.logger.log(logging.INFO, resp_log, logging_context)
                 self._log_resp(self.log_level, response, logging_context)
-        elif response.status_code in range(500, 600):
-            self.logger.log_error(logging.INFO, resp_log, logging_context)
-            self._log_resp(logging.ERROR, response, logging_context)
-        else:
-            self.logger.log(logging.INFO, resp_log, logging_context)
-            self._log_resp(self.log_level, response, logging_context)
-
         return response
 
     def _get_logging_context(self, request, response):

test_urls.py

@@ -2,8 +2,9 @@
 
 from django.conf.urls import url
 from django.http import HttpResponse
+from django.http import request
 from django.views import View
-from request_logging.decorators import no_logging
+from request_logging.decorators import no_logging, opt_into_logging
 from rest_framework import viewsets, routers, VERSION
 
 # DRF 3.8.2 is used in python versions 3.4 and older, which needs special handling
@@ -27,6 +28,11 @@ def post(self, request):
 def view_func(request):
     return HttpResponse(status=200, body="view_func with no logging")
 
+def ok(request):
+    return HttpResponse(status=200, body="OK")
+
+def internal_server_error(request):
+    return HttpResponse(status=500, body="Internal Server Error")
 
 @no_logging('Custom message')
 def view_msg(request):
@@ -40,7 +46,6 @@ def dont_log_silent(request):
 def dont_log_empty_response_body(request):
     return HttpResponse(status=201)
 
-
 class UnannotatedDRF(viewsets.ModelViewSet):
     @no_logging("DRF explicit annotation")
     def list(self, request):
@@ -70,4 +75,6 @@ def partial_update(self, request, *args, **kwargs):
     url(r'^test_msg$', view_msg),
     url(r'^dont_log_empty_response_body$', dont_log_empty_response_body),
     url(r'^dont_log_silent$', dont_log_silent),
+    url(r'^ok$', ok),
+    url(r'^internal_server_error$', internal_server_error),
 ] + router.urls

tests.py

@@ -142,6 +142,7 @@ def test_request_headers_sensitive_logged(self, mock_log):
     def test_response_headers_logged(self, mock_log):
         request = self.factory.post("/somewhere")
         response = mock.MagicMock()
+        response.status_code = 200
         response.get.return_value = 'application/json'
         response._headers = {'test_headers': 'test_headers'}
         self.middleware.process_response(request, response)
@@ -206,6 +207,7 @@ def test_request_logging_context(self, mock_log):
     def test_response_logging_context(self, mock_log):
         request = self.factory.post("/somewhere")
         response = mock.MagicMock()
+        response.status_code = 200
         response.get.return_value = 'application/json'
         response._headers = {'test_headers': 'test_headers'}
         self.middleware.process_response(request, response)
@@ -442,7 +444,6 @@ def test_still_logs_path(self, mock_log):
         self.middleware.process_request(request)
         self._assert_logged(mock_log, uri)
 
-
 @mock.patch.object(request_logging.middleware, "request_logger")
 class DRFTestCase(BaseLogTestCase):
     def setUp(self):
@@ -473,5 +474,48 @@ def test_non_existent_drf_route_logs(self, mock_log):
         self._assert_not_logged(mock_log, "had you")
 
 
+@mock.patch.object(request_logging.middleware, "request_logger")
+class LoggingOptInTestCase(BaseLogTestCase):
+    def setUp(self):
+        from django.urls import set_urlconf
+        set_urlconf('test_urls')
+        self.factory = RequestFactory()
+
+    def test_opt_into_logging_conditionals(self, mock_log):
+        def test_request_conditional(request):
+            return request.get_full_path() == "/ok"
+
+        def test_response_conditional(request):
+            return response.status_code == 418
+
+        with override_settings(
+            REQUEST_LOGGING_OPT_IN_CONDITIONAL=test_request_conditional,
+            RESPONSE_LOGGING_OPT_IN_CONDITIONAL=test_response_conditional,
+        ):
+            body = u"some super secret body"
+            request = self.factory.post("/ok", data={"file": body})
+            LoggingMiddleware().process_request(request)
+
+            self._assert_logged(mock_log, "file")
+            self._assert_logged(mock_log, "body")
+
+            mock_log.reset_mock()
+
+            request = self.factory.post("/internal_server_error", data={"foo": "bar"})
+            LoggingMiddleware().process_request(request)
+            response = mock.MagicMock()
+            response.status_code = 418
+            response.content = "bazqux"
+            response.get.return_value = "application/json"
+            response._headers = {'test_headers': 'test_headers'}
+            response.streaming = False
+            LoggingMiddleware().process_response(request, response)
+
+            self._assert_not_logged(mock_log, "foo")
+            self._assert_not_logged(mock_log, "bar")
+            self._assert_logged(mock_log, response.content)
+
+
+
 if __name__ == '__main__':
     unittest.main()