From 508c17b9e05821b70027ce1bc4f47598c2e4e29b Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 27 Jun 2020 13:53:48 +0300 Subject: [PATCH 1/8] Added silent flag which completely disables the logging of an endpoint --- request_logging/decorators.py | 7 ++++--- request_logging/middleware.py | 22 +++++++++++++--------- test_urls.py | 4 ++++ tests.py | 8 ++++++++ 4 files changed, 29 insertions(+), 12 deletions(-) diff --git a/request_logging/decorators.py b/request_logging/decorators.py index 75816cd..5d0d94b 100644 --- a/request_logging/decorators.py +++ b/request_logging/decorators.py @@ -1,9 +1,10 @@ from functools import wraps -from .middleware import NO_LOGGING_ATTR, NO_LOGGING_MSG +from .middleware import NO_LOGGING_ATTR, NO_LOGGING_MSG_ATTR, NO_LOGGING_MSG -def no_logging(msg=None): +def no_logging(msg=None, silent=False): def wrapper(func): - setattr(func, NO_LOGGING_ATTR, msg if msg else NO_LOGGING_MSG) + setattr(func, NO_LOGGING_ATTR, True) + setattr(func, NO_LOGGING_MSG_ATTR, (msg if msg else NO_LOGGING_MSG) if not silent else None) return func return wrapper diff --git a/request_logging/middleware.py b/request_logging/middleware.py index 917c74d..7d780cd 100644 --- a/request_logging/middleware.py +++ b/request_logging/middleware.py @@ -26,6 +26,7 @@ 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') @@ -106,9 +107,10 @@ def __call__(self, request): return response def process_request(self, request): - skip_logging_because = self._should_log_route(request) - if skip_logging_because: - return self._skip_logging_request(request, skip_logging_because) + skip_logging, because = self._should_log_route(request) + if skip_logging: + if because is not None: + return self._skip_logging_request(request, because) else: return self._log_request(request) @@ -122,7 +124,7 @@ def _should_log_route(self, request): try: route_match = resolve(request.path, urlconf=urlconf) except Resolver404: - return None + return False, None method = request.method.lower() view = route_match.func @@ -139,8 +141,9 @@ 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, None) - return no_logging + no_logging = getattr(func, NO_LOGGING_ATTR, False) + no_logging_msg = getattr(func, NO_LOGGING_MSG_ATTR, None) + return no_logging, no_logging_msg def _skip_logging_request(self, request, reason): method_path = "{} {}".format(request.method, request.get_full_path()) @@ -181,9 +184,10 @@ 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_because: - self.logger.log_error(logging.INFO, resp_log, {'args': {}, 'kwargs': { 'extra' : { 'no_logging': skip_logging_because } }}) + 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) diff --git a/test_urls.py b/test_urls.py index 233006e..496e024 100644 --- a/test_urls.py +++ b/test_urls.py @@ -31,6 +31,9 @@ def view_func(request): def view_msg(request): return HttpResponse(status=200, body="view_msg with no logging with a custom reason why") +@no_logging(silent=True) +def dont_log_silent(request): + return HttpResponse(status=200, body="view_msg with silent flag set") @no_logging('Empty response body') def dont_log_empty_response_body(request): @@ -65,4 +68,5 @@ def partial_update(self, request, *args, **kwargs): url(r'^test_func$', view_func), 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), ] + router.urls diff --git a/tests.py b/tests.py index 8bc6b34..21650e1 100755 --- a/tests.py +++ b/tests.py @@ -405,6 +405,14 @@ def test_no_logging_decorator_custom_msg(self, mock_log): self._assert_not_logged(mock_log, NO_LOGGING_MSG) self._assert_logged(mock_log, 'Custom message') + def test_no_logging_decorator_silent(self, mock_log): + body = u"some super secret body" + request = self.factory.post("/dont_log_silent", data={"file": body}) + self.middleware.process_request(request) + self._assert_not_logged(mock_log, body) + self._assert_not_logged(mock_log, NO_LOGGING_MSG) + self._assert_not_logged(mock_log, 'not logged because') + def test_no_logging_empty_response_body(self, mock_log): body = u"our work of art" request = self.factory.post("/dont_log_empty_response_body", data={"file": body}) From 7ba6cd50bcba7e02102ec8e19c71e853617f702c Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 27 Jun 2020 14:23:29 +0300 Subject: [PATCH 2/8] Fixed tests - drf 3.11 doesn't support python 3.4 --- requirements-dev.txt | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/requirements-dev.txt b/requirements-dev.txt index 3da1c08..0386dcd 100644 --- a/requirements-dev.txt +++ b/requirements-dev.txt @@ -4,5 +4,5 @@ django>=1.11.20,<2.0 ; python_version < '3.0' django>=1.11.20,<3.0 ; python_version >= '3.0' and python_version < '3.6' django>=2.0,<3.1.0 ; python_version >= '3.6' coverage==4.4.2 -djangorestframework==3.8.2 ; python_version < '3.0' -djangorestframework==3.11.0 ; python_version > '3.0' +djangorestframework==3.8.2 ; python_version <= '3.4' +djangorestframework==3.11.0 ; python_version >= '3.5' From 544cd296b34458df44a5216de80d02350ec6aed5 Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 27 Jun 2020 14:38:27 +0300 Subject: [PATCH 3/8] Fix of breaking tests when working with DRF 3.8.2 --- test_urls.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/test_urls.py b/test_urls.py index 496e024..05e5c00 100644 --- a/test_urls.py +++ b/test_urls.py @@ -4,9 +4,10 @@ from django.http import HttpResponse from django.views import View from request_logging.decorators import no_logging -from rest_framework import viewsets, routers +from rest_framework import viewsets, routers, VERSION -IS_PYTHON_27 = sys.version_info[0] < 3 +# DRF 3.8.2 is used in python versions 3.4 and older, which needs special handling +IS_DRF_382 = sys.version_info <= (3, 4) def general_resource(request): @@ -51,7 +52,7 @@ def partial_update(self, request, *args, **kwargs): router = routers.SimpleRouter(trailing_slash=False) -if IS_PYTHON_27: +if IS_DRF_382: last_arguments = { "base_name": "widgets" } From a451775cd4bfdb8018e518ce79a0a48229a2431a Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 21 Nov 2020 18:06:49 +0200 Subject: [PATCH 4/8] Added REQUEST_LOGGING_SENSITIVE_VIEWS option --- README.md | 3 +++ request_logging/middleware.py | 17 ++++++++++++++--- 2 files changed, 17 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 5253ad4..9c2d8a9 100644 --- a/README.md +++ b/README.md @@ -73,6 +73,9 @@ By default, HTTP status codes between 400 - 499 are logged at ERROR level. You If you set `REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL=logging.INFO` they will be logged the same as normal requests. ### 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_SENSITIVE_VIEWS +A list of views (or view methods in case of class based views) that should not be logged. This has the same behaviour as the no_logging decorator, but can be used in case of 3rd party modules where the source cannot be modified +`REQUEST_LOGGING_SENSITIVE_VIEWS = ['dj_rest_auth.views.LoginView.post']` ## Deploying, Etc. diff --git a/request_logging/middleware.py b/request_logging/middleware.py index e7d488d..08a6674 100644 --- a/request_logging/middleware.py +++ b/request_logging/middleware.py @@ -16,6 +16,7 @@ DEFAULT_COLORIZE = True DEFAULT_MAX_BODY_LENGTH = 50000 # log no more than 3k bytes of content DEFAULT_SENSITIVE_HEADERS = ["HTTP_AUTHORIZATION", "HTTP_PROXY_AUTHORIZATION"] +DEFAULT_SENSITIVE_VIEWS = [] SETTING_NAMES = { "log_level": "REQUEST_LOGGING_DATA_LOG_LEVEL", "http_4xx_log_level": "REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL", @@ -23,6 +24,7 @@ "colorize": "REQUEST_LOGGING_ENABLE_COLORIZE", "max_body_length": "REQUEST_LOGGING_MAX_BODY_LENGTH", "sensitive_headers": "REQUEST_LOGGING_SENSITIVE_HEADERS", + "sensitive_views": "REQUEST_LOGGING_SENSITIVE_VIEWS", } BINARY_REGEX = re.compile(r"(.+Content-Type:.*?)(\S+)/(\S+)(?:\r\n)*(.+)", re.S | re.I) BINARY_TYPES = ("image", "application") @@ -71,6 +73,7 @@ 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.sensitive_views = getattr(settings, SETTING_NAMES["sensitive_views"], DEFAULT_SENSITIVE_VIEWS) if not isinstance(self.sensitive_headers, list): raise ValueError( "{} should be list. {} is not list.".format(SETTING_NAMES["sensitive_headers"], self.sensitive_headers) @@ -123,6 +126,16 @@ def process_request(self, request, response=None): else: return self._log_request(request, response) + def _should_log_view(self, func): + full_path = '.'.join([func.__module__, func.__qualname__]) + if full_path in self.sensitive_views: + no_logging = True + no_logging_msg = NO_LOGGING_MSG + else: + no_logging = getattr(func, NO_LOGGING_ATTR, False) + no_logging_msg = getattr(func, NO_LOGGING_MSG_ATTR, None) + return no_logging, no_logging_msg + def _should_log_route(self, request): # request.urlconf may be set by middleware or application level code. # Use this urlconf if present or default to None. @@ -150,9 +163,7 @@ 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 self._should_log_view(func) def _skip_logging_request(self, request, reason): method_path = "{} {}".format(request.method, request.get_full_path()) From 337b58cdca4e5cb606a55e450a6824815bc9c8b5 Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 21 Nov 2020 18:07:21 +0200 Subject: [PATCH 5/8] Fixed minor english syntax error --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 9c2d8a9..afe3ed6 100644 --- a/README.md +++ b/README.md @@ -58,7 +58,7 @@ A `no_logging` decorator is included for views with sensitive data. 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 -You can customized some behaves of django-request-logging by following settings in Django `settings.py`. +You can customize some behaviours of django-request-logging by following settings in Django `settings.py`. ### REQUEST_LOGGING_DATA_LOG_LEVEL By default, data will log in DEBUG level, you can change to other valid level (Ex. logging.INFO) if need. ### REQUEST_LOGGING_ENABLE_COLORIZE From 5fef39cc5a6009dede40a70f5c55ace64f0fe8a7 Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Sat, 21 Nov 2020 18:11:35 +0200 Subject: [PATCH 6/8] Update tests.py Removed wrongly merged function --- tests.py | 8 -------- 1 file changed, 8 deletions(-) diff --git a/tests.py b/tests.py index 5e06891..081bbff 100755 --- a/tests.py +++ b/tests.py @@ -409,14 +409,6 @@ def test_no_logging_decorator_silent(self, mock_log): self._assert_not_logged(mock_log, NO_LOGGING_MSG) self._assert_not_logged(mock_log, "not logged because") - def test_no_logging_decorator_silent(self, mock_log): - body = u"some super secret body" - request = self.factory.post("/dont_log_silent", data={"file": body}) - self.middleware.process_request(request) - self._assert_not_logged(mock_log, body) - self._assert_not_logged(mock_log, NO_LOGGING_MSG) - self._assert_not_logged(mock_log, 'not logged because') - def test_no_logging_empty_response_body(self, mock_log): body = u"our work of art" request = self.factory.post("/dont_log_empty_response_body", data={"file": body}) From aeaeedd15e857f6091053beb4b73fbaa131e20f3 Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Fri, 20 Aug 2021 22:07:52 +0300 Subject: [PATCH 7/8] Added feature to log the processing time of a request --- README.md | 5 +++-- request_logging/middleware.py | 21 +++++++++++++++++++-- 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 2a3ff79..f6f88a6 100644 --- a/README.md +++ b/README.md @@ -72,11 +72,12 @@ By default, max length of a request body and a response content is cut to 50000 By default, HTTP status codes between 400 - 499 are logged at ERROR level. You can set `REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL=logging.WARNING` (etc) to override this. If you set `REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL=logging.INFO` they will be logged the same as normal requests. ### 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']` +The value of the headers defined in this settings will be replaced with `'*****'` to hide the sensitive information while logging. By default it is set as `REQUEST_LOGGING_SENSITIVE_HEADERS = ["HTTP_AUTHORIZATION", "HTTP_PROXY_AUTHORIZATION"]` ### REQUEST_LOGGING_SENSITIVE_VIEWS A list of views (or view methods in case of class based views) that should not be logged. This has the same behaviour as the no_logging decorator, but can be used in case of 3rd party modules where the source cannot be modified `REQUEST_LOGGING_SENSITIVE_VIEWS = ['dj_rest_auth.views.LoginView.post']` -The value of the headers defined in this settings will be replaced with `'*****'` to hide the sensitive information while logging. By default it is set as `REQUEST_LOGGING_SENSITIVE_HEADERS = ["HTTP_AUTHORIZATION", "HTTP_PROXY_AUTHORIZATION"]` +### REQUEST_LOGGING_LOG_PROCESSING_TIME +Calculate the processing time of the request in milliseconds and append them in the response logging. Defaults to `False` ## Deploying, Etc. diff --git a/request_logging/middleware.py b/request_logging/middleware.py index ecd06a6..744e847 100644 --- a/request_logging/middleware.py +++ b/request_logging/middleware.py @@ -1,5 +1,6 @@ import logging import re +import time from django import VERSION as django_version from django.conf import settings @@ -23,6 +24,7 @@ "HTTP_AUTHORIZATION", "HTTP_PROXY_AUTHORIZATION" ] DEFAULT_SENSITIVE_VIEWS = [] +DEFAULT_LOG_PROCESSING_TIME = False SETTING_NAMES = { "log_level": "REQUEST_LOGGING_DATA_LOG_LEVEL", "http_4xx_log_level": "REQUEST_LOGGING_HTTP_4XX_LOG_LEVEL", @@ -31,6 +33,7 @@ "max_body_length": "REQUEST_LOGGING_MAX_BODY_LENGTH", "sensitive_headers": "REQUEST_LOGGING_SENSITIVE_HEADERS", "sensitive_views": "REQUEST_LOGGING_SENSITIVE_VIEWS", + "log_processing_time": "REQUEST_LOGGING_LOG_PROCESSING_TIME", } BINARY_REGEX = re.compile(r"(.+Content-Type:.*?)(\S+)/(\S+)(?:\r\n)*(.+)", re.S | re.I) BINARY_TYPES = ("image", "application") @@ -80,6 +83,7 @@ def __init__(self, get_response=None): 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.sensitive_views = getattr(settings, SETTING_NAMES["sensitive_views"], DEFAULT_SENSITIVE_VIEWS) + self.log_processing_time = getattr(settings, SETTING_NAMES["log_processing_time"], DEFAULT_LOG_PROCESSING_TIME) if not isinstance(self.sensitive_headers, list): raise ValueError( "{} should be list. {} is not list.".format(SETTING_NAMES["sensitive_headers"], self.sensitive_headers) @@ -119,9 +123,19 @@ def __init__(self, get_response=None): def __call__(self, request): self.cached_request_body = request.body + + if self.log_processing_time: + processing_start = time.time() + response = self.get_response(request) + + if self.log_processing_time: + processing_time = time.time() - processing_start + else: + processing_time = None + self.process_request(request, response) - self.process_response(request, response) + self.process_response(request, response, processing_time) return response def process_request(self, request, response=None): @@ -219,8 +233,11 @@ def _log_request_body(self, request, logging_context, log_level): else: self.logger.log(log_level, self._chunked_to_max(self.cached_request_body), logging_context) - def process_response(self, request, response): + def process_response(self, request, response, processing_time=None): resp_log = "{} {} - {}".format(request.method, request.get_full_path(), response.status_code) + if processing_time: + resp_log += ' [{} ms]'.format(int(processing_time*1000)) + skip_logging, because = self._should_log_route(request) if skip_logging: if because is not None: From a54a261fbc4afe8037322e1ead46fcd5929a525d Mon Sep 17 00:00:00 2001 From: Alexandros Nikolopoulos Date: Thu, 16 Feb 2023 15:43:15 +0200 Subject: [PATCH 8/8] Fixed issue when path is non-existent --- request_logging/middleware.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/request_logging/middleware.py b/request_logging/middleware.py index 744e847..45d4a05 100644 --- a/request_logging/middleware.py +++ b/request_logging/middleware.py @@ -147,8 +147,12 @@ def process_request(self, request, response=None): return self._log_request(request, response) def _should_log_view(self, func): - full_path = '.'.join([func.__module__, func.__qualname__]) - if full_path in self.sensitive_views: + if func: + full_path = '.'.join([func.__module__, func.__qualname__]) + else: + full_path = None + + if full_path is not None and full_path in self.sensitive_views: no_logging = True no_logging_msg = NO_LOGGING_MSG else: