Merge pull request Raekkeri#5 from Raekkeri/request-id

Request-id

Author: Raekkeri

README.md

@@ -60,7 +60,20 @@ MIDDLEWARE = [
 ]
 ```
 
-This will start storing the request logs using the default `STORAGE_CLASS`, which in fact just uses Python logger named `requestlogs`. Now you can, for example, redirect these logs to a file with the following `LOGGING` configuration:
+Set `'requestlogs.views.exception_handler'` as rest_framework's exception handler
+(this will make sure requestlog entry has all possible data available about the
+request in case of a 500 error):
+
+```python
+REST_FRAMEWORK={
+    ...
+    'EXCEPTION_HANDLER': 'requestlogs.views.exception_handler',
+}
+```
+
+The middleware is now ready to start storing requestlog entries using the default
+`STORAGE_CLASS`, which in fact just uses Python logger named `requestlogs`. Now you can,
+for example, redirect these logs to a file with the following `LOGGING` configuration:
 
 ```python
 LOGGING = {
@@ -77,6 +90,7 @@ LOGGING = {
         'requestlogs': {
             'handlers': ['requestlogs_to_file'],
             'level': 'INFO',
+            'propagate': False,
         },
     },
 }
@@ -90,6 +104,7 @@ Requestlogs can be customized using Django settings. The following shows the def
 REQUESTLOGS = {
     'STORAGE_CLASS': 'requestlogs.storages.LoggingStorage',
     'ENTRY_CLASS': 'requestlogs.entries.RequestLogEntry',
+    'SERIALIZER_CLASS': 'requestlogs.storages.BaseEntrySerializer',
     'SECRETS': ['password', 'token'],
     'ATTRIBUTE_NAME': '_requestlog',
 }
@@ -99,7 +114,123 @@ REQUESTLOGS = {
   - Path to the Python class which will handle storing the log entries. Override this if you only need to reimplement the storage mechanism. This may be the case e.g. when choosing what data to store.
 - **ENTRY_CLASS**
   - Path to the Python class which handles the construction of the complete requestlogs entry. Override this for full customization of the requestlog entry behaviour.
+- **SERIALIZER_CLASS**
+  - Path to the serializer class which is used to serialize the requestlog entry before storage. By default this is a subclass of `rest_framework.serializers.Serializer`.
 - **SECRETS**
   - List of keys in request/response data which will be replaced with `'***'` in the stored entry.
 - **ATTRIBUTE_NAME**
   - django-requestlogs internally attaches the entry object to the Django request object, and uses this attribute name. Override if it causes collisions.
+
+
+# Logging with Request ID
+
+django-requestlogs also contains a middleware and logging helpers to associate a
+request-specific identifier (uuid) to logging messages. This aims to help
+distinguishing messages to certain request-response cycle, which can be useful
+in an application that receives a high number of requests.
+
+The request id is added to the standard logging messages (Django application logs)
+by specifying a custom formatter and using the provided logging filter.
+The request id can be stored to requestlog entries as well.
+The middleware to enable the request id logging does not require the core requestlogs
+middleware to be installed.
+
+Under the hood the request id is implemented with help of `threading.local()`.
+
+## Installation
+
+The feature is enabled by adding `requestlogs.middleware.RequestLogsMiddleware`
+to the `MIDDLEWARE` setting:
+
+```python
+MIDDLEWARE = [
+    ...
+    'requestlogs.middleware.RequestLogsMiddleware',
+    'requestlogs.middleware.RequestIdMiddleware',
+]
+```
+
+Once installed, the application logs should start showing messages with a format such as
+the following:
+
+```
+2019-07-18 11:56:07,261 INFO 954fb004fb404751a2fa33326101442c urls:31 Handling GET request
+2019-07-18 11:56:07,262 DEBUG 954fb004fb404751a2fa33326101442c urls:32 No parameters given
+2019-07-18 11:56:07,262 INFO 954fb004fb404751a2fa33326101442c urls:33 All good
+```
+
+To add the request id to requestlog entries as well, you can use the provided serializer
+class as a starting point:
+
+```python
+REQUESTLOGS = {
+    ...
+    'SERIALIZER_CLASS': 'requestlogs.storages.RequestIdEntrySerializer',
+}
+```
+
+## Configuration
+
+The middleware has some additional configuration possiblities:
+
+
+```python
+REQUESTLOGS = {
+    ...
+    'REQUEST_ID_HTTP_HEADER': 'X_DJANGO_REQUEST_ID',
+    'REQUEST_ID_ATTRIBUTE_NAME': 'request_id',
+}
+```
+- **REQUEST_ID_HTTP_HEADER**
+  - If set, the value of this request header is used as request id (instead of it being
+    randomly generated). This must be a valid uuid. One use case for this feature is in
+    microservice architecture, where a micreservice calls another, internal microservice.
+    Having the log messages of both applications to be formatted with same request id
+    might be the preferred outcome.
+- **REQUEST_ID_ATTRIBUTE_NAME**
+  - The attribute name which is used internally to attach request id to
+    `threading.locals()`. Override if it causes collisions.
+
+To add the request id to logging messages of your Django application, use the provided
+logging filter and include `request_id` to the log formatter.
+Here is the complete logging configuration:
+
+```python
+LOGGING = {
+    'version': 1,
+    'disable_existing_loggers': False,
+    'handlers': {
+        'requestlogs_to_file': {
+            'level': 'INFO',
+            'class': 'logging.FileHandler',
+            'filename': '/tmp/requestlogs.log',
+        },
+        'root': {
+            'class': 'logging.StreamHandler',
+            'filters': ['request_id_context'],
+            'formatter': 'verbose',
+        },
+    },
+    'loggers': {
+        '': {
+            'handlers': ['root'],
+            'level': 'DEBUG',
+        },
+        'requestlogs': {
+            'handlers': ['requestlogs_to_file'],
+            'level': 'INFO',
+            'propagate': False,
+        },
+    },
+    'filters': {
+        'request_id_context': {
+            '()': 'requestlogs.logging.RequestIdContext',
+        },
+    },
+    'formatters': {
+        'verbose': {
+            'format': '%(asctime)s %(levelname)s %(request_id)s %(module)s:%(lineno)s %(message)s'
+        },
+    },
+}
+```

requestlogs/base.py

@@ -7,7 +7,10 @@
     'ATTRIBUTE_NAME': '_requestlog',
     'ENTRY_CLASS': 'requestlogs.entries.RequestLogEntry',
     'STORAGE_CLASS': 'requestlogs.storages.LoggingStorage',
+    'SERIALIZER_CLASS': 'requestlogs.storages.BaseEntrySerializer',
     'SECRETS': ['password', 'token'],
+    'REQUEST_ID_ATTRIBUTE_NAME': 'request_id',
+    'REQUEST_ID_HTTP_HEADER': None,
 }
 
 
@@ -18,6 +21,8 @@ def populate_settings(_settings):
         _settings[k] = v
     _settings['ENTRY_CLASS'] = import_string(_settings['ENTRY_CLASS'])
     _settings['STORAGE_CLASS'] = import_string(_settings['STORAGE_CLASS'])
+    _settings['SERIALIZER_CLASS'] = import_string(
+        _settings['SERIALIZER_CLASS'])
 
 
 SETTINGS = {}

requestlogs/entries.py

@@ -5,6 +5,7 @@
 from rest_framework.request import Request
 
 from .base import SETTINGS
+from .logging import get_request_id
 from .utils import remove_secrets, get_client_ip
 
 
@@ -28,6 +29,10 @@ def query_params(self):
     def full_path(self):
         return self.request.get_full_path()
 
+    @property
+    def request_id(self):
+        return get_request_id()
+
 
 class DRFRequestHandler(RequestHandler):
     @property

requestlogs/logging.py

@@ -0,0 +1,33 @@
+import logging
+import uuid
+import threading
+
+from .base import SETTINGS
+
+local = threading.local()
+
+
+def get_request_id():
+    return getattr(local, SETTINGS['REQUEST_ID_ATTRIBUTE_NAME'], '')
+
+
+def set_request_id(_uuid=None):
+    _uuid = _uuid or uuid.uuid4().hex
+    setattr(local, SETTINGS['REQUEST_ID_ATTRIBUTE_NAME'], _uuid)
+    return _uuid
+
+
+def validate_uuid(_uuid):
+    try:
+        val = uuid.UUID(_uuid, version=4)
+    except (ValueError, TypeError):
+        return None
+
+    return _uuid if val.hex == _uuid else None
+
+
+class RequestIdContext(logging.Filter):
+    def filter(self, record):
+        setattr(record, SETTINGS['REQUEST_ID_ATTRIBUTE_NAME'],
+                get_request_id())
+        return True

requestlogs/middleware.py

@@ -1,3 +1,5 @@
+from .base import SETTINGS
+from .logging import set_request_id, validate_uuid
 from . import get_requestlog_entry
 
 
@@ -14,3 +16,13 @@ def __call__(self, request):
         response = self.get_response(request)
         get_requestlog_entry(request).finalize(response)
         return response
+
+
+class RequestIdMiddleware(object):
+    def __init__(self, get_response):
+        self.get_response = get_response
+
+    def __call__(self, request):
+        reuse_request_id = request.META.get(SETTINGS['REQUEST_ID_HTTP_HEADER'])
+        set_request_id(validate_uuid(reuse_request_id))
+        return self.get_response(request)

requestlogs/storages.py

@@ -3,6 +3,8 @@
 
 from rest_framework import serializers
 
+from .base import SETTINGS
+
 
 logger = logging.getLogger('requestlogs')
 
@@ -12,13 +14,14 @@ def to_representation(self, value):
         return json.dumps(value)
 
 
-class BaseEntrySerializer(serializers.Serializer):
-    class RequestSerializer(serializers.Serializer):
-        method = serializers.CharField(read_only=True)
-        full_path = serializers.CharField(read_only=True)
-        data = JsonDumpField(read_only=True)
-        query_params = JsonDumpField(read_only=True)
+class BaseRequestSerializer(serializers.Serializer):
+    method = serializers.CharField(read_only=True)
+    full_path = serializers.CharField(read_only=True)
+    data = JsonDumpField(read_only=True)
+    query_params = JsonDumpField(read_only=True)
+
 
+class BaseEntrySerializer(serializers.Serializer):
     class ResponseSerializer(serializers.Serializer):
         status_code = serializers.IntegerField(read_only=True)
         data = JsonDumpField(read_only=True)
@@ -31,16 +34,29 @@ class UserSerializer(serializers.Serializer):
     execution_time = serializers.DurationField(read_only=True)
     timestamp = serializers.DateTimeField(read_only=True)
     ip_address = serializers.CharField(read_only=True)
-    request = RequestSerializer(read_only=True)
+    request = BaseRequestSerializer(read_only=True)
     response = ResponseSerializer(read_only=True)
     user = UserSerializer()
 
 
-class LoggingStorage(object):
-    serializer_class = BaseEntrySerializer
+class RequestIdEntrySerializer(BaseEntrySerializer):
+    class RequestSerializer(BaseRequestSerializer):
+        request_id = serializers.CharField()
 
-    def store(self, entry):
-        logger.info(self.prepare(entry))
+    request = RequestSerializer()
+
+
+class BaseStorage(object):
+    serializer_class = None
+
+    def get_serializer_class(self):
+        return (self.serializer_class if self.serializer_class else
+                SETTINGS['SERIALIZER_CLASS'])
 
     def prepare(self, entry):
-        return self.serializer_class(entry).data
+        return self.get_serializer_class()(entry).data
+
+
+class LoggingStorage(BaseStorage):
+    def store(self, entry):
+        logger.info(self.prepare(entry))