Feature django logging

README.rst

@@ -23,6 +23,7 @@ Features
   * `Flask 0.1x <http://flask.pocoo.org/>`__
   * `Sanic 0.5.x <https://github.com/channelcat/sanic>`__
   * `Falcon <https://falconframework.org/>`__
+  * `Django <https://www.djangoproject.com/>`__
   * Extensible to support others
 
 6. Includes CF-specific information (space id, app id, etc.) to logs.
@@ -137,6 +138,73 @@ Falcon
    app.add_route('/resource', Resource())
    falcon_logging.init(app)
 
+Django
+^^^^^^
+
+.. code:: bash
+
+    django-admin startproject example
+
+.. code:: python
+
+    # example/settings.py
+
+        MIDDLEWARES = [
+            # ...,
+            'sap.cf_logging.django_logging.LoggingMiddleware'
+        ]
+
+    # example/wsgi.py
+
+        # ...
+        from sap.cf_logging import django_logging
+
+        os.environ.setdefault("DJANGO_SETTINGS_MODULE", "sap_logtesting.settings")
+        django_logging.init()
+
+        # ...
+
+Create a new app
+
+.. code:: bash
+
+    python manage.py startapp example_app
+
+.. code:: python
+
+    # example_app/views.py
+
+        import logging
+
+        from django.http import HTTPResponse
+        from sap.cf_logging.core.constants import REQUEST_KEY
+
+        def index(request):
+            extra = {REQUEST_KEY: request}
+            logger = logging.getLogger('my.logger')
+            logger.info("Resource requested", extra=extra)
+            return HttpResponse("ok")
+
+    # example_app/urls.py
+
+        from django.conf.urls import url
+
+        from . import views
+
+        urlpatterns = [
+            url('^$', views.index)
+        ]
+
+    # example/urls.py
+
+        from django.contrib import admin
+        from django.conf.urls import url, include
+
+        urlpatterns = [
+            url('admin/', admin.site.urls),
+            url('example/', include('example_app.urls'))
+        ]
+
 General
 ^^^^^^^
 

conftest.py

@@ -1,4 +1,5 @@
 import sys
 
+
 if sys.version_info < (3, 5):
     collect_ignore = ['tests/test_sanic_logging.py']

sap/cf_logging/django_logging/__init__.py

@@ -0,0 +1,64 @@
+""" Logging support for Django based applications """
+import logging
+from datetime import datetime
+
+from sap import cf_logging
+from sap.cf_logging import defaults
+from sap.cf_logging.core.constants import REQUEST_KEY, RESPONSE_KEY
+from sap.cf_logging.core.framework import Framework
+from sap.cf_logging.django_logging.context import DjangoContext
+from sap.cf_logging.django_logging.request_reader import DjangoRequestReader
+from sap.cf_logging.django_logging.response_reader import DjangoResponseReader
+
+DJANGO_FRAMEWORK_NAME = 'django.framework'
+
+
+class LoggingMiddleware(object):
+    """ Django logging middleware """
+
+    def __init__(self, get_response, logger_name='cf.django.logger'):
+        self._logger_name = logger_name
+        self._get_response = get_response
+
+    def __call__(self, request):
+        self.process_request(request)
+        response = self._get_response(request)
+
+        response = self.process_response(request, response)
+        return response
+
+    def process_request(self, request):# pylint: disable=no-self-use
+        """
+        Process the request before routing it.
+
+        :param request: - Django Request object
+        """
+        framework = cf_logging.FRAMEWORK
+        cid = framework.request_reader.get_correlation_id(request)
+        framework.context.set_correlation_id(cid, request)
+        framework.context.set('request_started_at', datetime.utcnow(), request)
+
+    def process_response(self, request, response):
+        """
+        Post-processing of the response (after routing).
+
+        :param request: - Django Request object
+        :param request: - Django Response object
+        """
+        cf_logging.FRAMEWORK.context.set(
+            'response_sent_at', datetime.utcnow(), request)
+        extra = {REQUEST_KEY: request, RESPONSE_KEY: response}
+        logging.getLogger(self._logger_name).info('', extra=extra)
+        return response
+
+
+def init(level=defaults.DEFAULT_LOGGING_LEVEL):
+    """
+    Initializes logging in JSON format.
+
+    :param level: - valid log level from standard logging package (optional)
+    """
+    framework = Framework(DJANGO_FRAMEWORK_NAME, DjangoContext(),
+                          DjangoRequestReader(), DjangoResponseReader())
+
+    cf_logging.init(framework, level)

sap/cf_logging/django_logging/context.py

@@ -0,0 +1,24 @@
+"""
+Django logging context - used by the logging package to keep
+request specific data, needed for logging purposes.
+For example correlation_id needs to be stored during request processing,
+so all log entries contain it.
+"""
+
+from sap.cf_logging.core.context import Context
+
+
+def _init_context(request):
+    if not hasattr(request, 'context'):
+        request.context = {}
+
+class DjangoContext(Context):
+    """ Stores logging context in Django's request objecct """
+
+    def set(self, key, value, request):
+        _init_context(request)
+        request.context[key] = value
+
+    def get(self, key, request):
+        _init_context(request)
+        return request.context.get(key) if request else None

sap/cf_logging/django_logging/request_reader.py

@@ -0,0 +1,34 @@
+""" Django request reader """
+
+from sap.cf_logging import defaults
+from sap.cf_logging.core.request_reader import RequestReader
+
+
+class DjangoRequestReader(RequestReader):
+    """ Read log related properties out of Django request """
+
+    def get_remote_user(self, request):
+        return request.META.get('REMOTE_USER') or defaults.UNKNOWN
+
+    def get_protocol(self, request):
+        return request.scheme
+
+    def get_content_length(self, request):
+        return request.META.get('CONTENT_LENGTH') or defaults.UNKNOWN
+
+    def get_remote_ip(self, request):
+        return request.META.get('REMOTE_ADDR')
+
+    def get_remote_port(self, request):
+        return request.META.get('SERVER_PORT') or defaults.UNKNOWN
+
+    def get_http_header(self, request, header_name, default=None):
+        if request is None:
+            return default
+
+        if header_name in request.META:
+            return request.META.get(header_name)
+        if header_name.upper() in request.META:
+            return request.META.get(header_name.upper())
+
+        return default

sap/cf_logging/django_logging/response_reader.py

@@ -0,0 +1,15 @@
+""" Django response reader """
+from sap.cf_logging.core.response_reader import ResponseReader
+
+
+class DjangoResponseReader(ResponseReader):
+    """ Read log related properties out of Django response """
+
+    def get_status_code(self, response):
+        return response.status_code
+
+    def get_response_size(self, response):
+        return len(response.content)
+
+    def get_content_type(self, response):
+        return response.get('Content-Type')

test-requirements.txt

@@ -8,5 +8,6 @@ sonic182-json-validator==0.0.12
 pytest==3.6.2
 pytest-cov==2.5.1
 pytest-mock==1.6.3
-pylint
+pylint==1.9.2
 tox
+django

tests/common_test_params.py

@@ -22,7 +22,7 @@ def get_web_record_header_fixtures():
             'response_content_type': v_str('text/plain'),
             'request': v_str('/test/path')})
     ]
-    for header in ['x-Correlation-ID', 'X-CorrelationID', 'X-Request-ID', 'X-Vcap-Request-Id']:
+    for header in ['X-Correlation-ID', 'X-CorrelationID', 'X-Request-ID', 'X-Vcap-Request-Id']:
         test_cases.append(({header: '298ebf9d-be1d-11e7-88ff-2c44fd152864'},
                            {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152864')}))
 

tests/django_logging/test_app/settings.py

@@ -0,0 +1,17 @@
+""" Example django test app settings """
+SECRET_KEY = 'fake-key'
+INSTALLED_APPS = [
+    "tests",
+]
+
+DATABASES = {
+    'default': {
+        'ENGINE': 'django.db.backends.sqlite3'
+    }
+}
+
+ROOT_URLCONF = 'tests.django_logging.test_app.urls'
+
+MIDDLEWARE = [
+    'sap.cf_logging.django_logging.LoggingMiddleware',
+]

tests/django_logging/test_app/test_django_logging.py

@@ -0,0 +1,85 @@
+""" Module that tests the integration of cf_logging with Django """
+import sys
+import os
+import pytest
+
+from django.test import Client
+from django.conf.urls import url
+from django.conf import settings
+
+from sap import cf_logging
+from sap.cf_logging import django_logging
+from tests.log_schemas import WEB_LOG_SCHEMA
+from tests.common_test_params import (
+    v_str, get_web_record_header_fixtures
+)
+from tests.util import (
+    check_log_record,
+    enable_sensitive_fields_logging,
+    config_logger
+)
+
+from tests.django_logging.test_app.views import UserLoggingView
+
+
+os.environ['DJANGO_SETTINGS_MODULE'] = 'tests.django_logging.test_app.settings'
+
+
+@pytest.fixture(autouse=True)
+def before_each():
+    """ enable all fields to be logged """
+    enable_sensitive_fields_logging()
+    yield
+
+
+FIXTURE = get_web_record_header_fixtures()
+
+@pytest.mark.parametrize('headers, expected', FIXTURE)
+def test_django_request_log(headers, expected):
+    """ That the expected records are logged by the logging library """
+    _set_up_django_logging()
+    _check_django_request_log(headers, expected)
+
+
+def test_web_log():
+    """ That the custom properties are logged """
+    _user_logging({}, {'myproperty': 'myval'}, {'myproperty': v_str('myval')})
+
+
+def test_correlation_id():
+    """ Test the correlation id is logged when coming from the headers """
+    _user_logging(
+        {'X-CorrelationID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'},
+        {},
+        {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152860')}
+    )
+
+
+def _check_django_request_log(headers, expected):
+    _, stream = config_logger('cf.django.logger')
+
+    client = Client()
+    _check_expected_response(client.get('/test/path', **headers), body='Hello test!')
+    assert check_log_record(stream, WEB_LOG_SCHEMA, expected) == {}
+
+
+# Helper functions
+def _set_up_django_logging():
+    cf_logging._SETUP_DONE = False # pylint: disable=protected-access
+    django_logging.init()
+
+
+def _check_expected_response(response, status_code=200, body='ok'):
+    assert response.status_code == status_code
+    if body is not None:
+        assert response.content.decode() == body
+
+def _user_logging(headers, extra, expected):
+    sys.modules[settings.ROOT_URLCONF].urlpatterns.append(
+        url('^test/user/logging$', UserLoggingView.as_view(),
+            {'extra': extra, 'expected': expected}))
+
+
+    _set_up_django_logging()
+    client = Client()
+    _check_expected_response(client.get('/test/user/logging', **headers))

tests/django_logging/test_app/urls.py

@@ -0,0 +1,9 @@
+""" Urls for example django test app """
+from django.conf.urls import url
+
+from tests.django_logging.test_app.views import IndexView
+
+# pylint: disable=invalid-name
+urlpatterns = [
+    url("^test/path$", IndexView.as_view(), name='log-index')
+]

tests/django_logging/test_app/views.py

@@ -0,0 +1,34 @@
+""" Views for example django test app """
+import logging
+
+from django.http import HttpResponse
+from django.views import generic
+
+from sap.cf_logging.core.constants import REQUEST_KEY
+from tests.util import config_logger, check_log_record
+from tests.log_schemas import JOB_LOG_SCHEMA
+
+# pylint: disable=unused-argument
+
+class IndexView(generic.View):
+    """ View that is hit on the index route """
+    def get(self, request): # pylint: disable=no-self-use
+        """ Return a basic http response """
+        return HttpResponse("Hello test!", content_type='text/plain')
+
+
+class UserLoggingView(generic.View):
+    """ View that logs custom user information """
+    def __init__(self, *args, **kwargs):
+        self.logger, self.stream = config_logger('user.logging')
+        super(UserLoggingView, self).__init__(*args, **kwargs)
+
+    def get(self, request, *args, **kwargs):
+        """ Log a custom user message with the logger """
+        expected = kwargs.get('expected') or {}
+        extra = kwargs.get('extra') or {}
+        extra.update({REQUEST_KEY: request})
+
+        self.logger.log(logging.INFO, 'in route headers', extra=extra)
+        assert check_log_record(self.stream, JOB_LOG_SCHEMA, expected) == {}
+        return HttpResponse("ok", content_type='text/plain')