diff --git a/README.rst b/README.rst index 7a3f5e6..17472d9 100644 --- a/README.rst +++ b/README.rst @@ -23,6 +23,7 @@ Features * `Flask 0.1x `__ * `Sanic 0.5.x `__ * `Falcon `__ + * `Django `__ * 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 ^^^^^^^ diff --git a/conftest.py b/conftest.py index 2912813..3f00811 100644 --- a/conftest.py +++ b/conftest.py @@ -1,4 +1,5 @@ import sys + if sys.version_info < (3, 5): collect_ignore = ['tests/test_sanic_logging.py'] diff --git a/sap/cf_logging/django_logging/__init__.py b/sap/cf_logging/django_logging/__init__.py new file mode 100644 index 0000000..b8cb95d --- /dev/null +++ b/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) diff --git a/sap/cf_logging/django_logging/context.py b/sap/cf_logging/django_logging/context.py new file mode 100644 index 0000000..ea1acea --- /dev/null +++ b/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 diff --git a/sap/cf_logging/django_logging/request_reader.py b/sap/cf_logging/django_logging/request_reader.py new file mode 100644 index 0000000..e912974 --- /dev/null +++ b/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 diff --git a/sap/cf_logging/django_logging/response_reader.py b/sap/cf_logging/django_logging/response_reader.py new file mode 100644 index 0000000..7338f93 --- /dev/null +++ b/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') diff --git a/test-requirements.txt b/test-requirements.txt index 4a0be2c..4de55c8 100644 --- a/test-requirements.txt +++ b/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 diff --git a/tests/common_test_params.py b/tests/common_test_params.py index 78debfc..e971738 100644 --- a/tests/common_test_params.py +++ b/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')})) diff --git a/tests/django_logging/__init__.py b/tests/django_logging/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/django_logging/test_app/__init__.py b/tests/django_logging/test_app/__init__.py new file mode 100644 index 0000000..e69de29 diff --git a/tests/django_logging/test_app/settings.py b/tests/django_logging/test_app/settings.py new file mode 100644 index 0000000..11df7b2 --- /dev/null +++ b/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', +] diff --git a/tests/django_logging/test_app/test_django_logging.py b/tests/django_logging/test_app/test_django_logging.py new file mode 100644 index 0000000..4a74bde --- /dev/null +++ b/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)) diff --git a/tests/django_logging/test_app/urls.py b/tests/django_logging/test_app/urls.py new file mode 100644 index 0000000..f4c2337 --- /dev/null +++ b/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') +] diff --git a/tests/django_logging/test_app/views.py b/tests/django_logging/test_app/views.py new file mode 100644 index 0000000..d204795 --- /dev/null +++ b/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') diff --git a/tests/test_falcon_logging.py b/tests/test_falcon_logging.py index 9e50e06..53d56d3 100644 --- a/tests/test_falcon_logging.py +++ b/tests/test_falcon_logging.py @@ -13,8 +13,8 @@ ) from tests.util import ( check_log_record, - enable_sensitive_fields_logging, - config_logger + config_logger, + enable_sensitive_fields_logging ) @@ -94,7 +94,7 @@ def test_web_log(): def test_correlation_id(): """ Test the correlation id is logged when coming from the headers """ _user_logging( - {'X-CorrelationID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, + {'X-Correlation-ID': '298ebf9d-be1d-11e7-88ff-2c44fd152860'}, {}, {'correlation_id': v_str('298ebf9d-be1d-11e7-88ff-2c44fd152860')} )