diff --git a/README.rst b/README.rst index 29eae74..53c188d 100644 --- a/README.rst +++ b/README.rst @@ -93,7 +93,7 @@ Sanic from sanic.response import HTTPResponse from sap.cf_logging import sanic_logging - from sap.cf_logging.core.constants import REQUEST_KEY, + from sap.cf_logging.core.constants import REQUEST_KEY app = sanic.Sanic('test.cf_logging') sanic_logging.init(app) @@ -108,6 +108,31 @@ Sanic This is needed in order to get the *correlation_id* generated at the beginning of the request or fetched from the HTTP headers. +Falcon +^^^^^^ + +.. code:: python + + + import falcon + from sap.cf_logging import falcon_logging + + + class Resource: + def on_get(self, req, resp): + # Use the log() method of the req object to log additional messages + req.log('Resource requested') + resp.media = {'name': 'Cloud Foundry'} + + + app = falcon.API(middleware=[ + falcon_logging.LoggingMiddleware() + ]) + app.add_route('/resource', Resource()) + falcon_logging.init(app) + +**Note**: Use the ``log`` method of ``req`` since it will include the ``correlation_id`` from the ``req`` object in the logs. + General ^^^^^^^ diff --git a/sap/cf_logging/core/request_reader.py b/sap/cf_logging/core/request_reader.py index 863d2da..80459b3 100644 --- a/sap/cf_logging/core/request_reader.py +++ b/sap/cf_logging/core/request_reader.py @@ -40,6 +40,8 @@ def get_http_header(self, request, header_name, default=None): if header_name in request.headers: return request.headers.get(header_name) + if header_name.upper() in request.headers: + return request.headers.get(header_name.upper()) return default def get_remote_user(self, request): diff --git a/sap/cf_logging/falcon_logging/__init__.py b/sap/cf_logging/falcon_logging/__init__.py new file mode 100644 index 0000000..9f572d5 --- /dev/null +++ b/sap/cf_logging/falcon_logging/__init__.py @@ -0,0 +1,62 @@ +import logging +from datetime import datetime + +import falcon + +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.falcon_logging.context import FalconContext +from sap.cf_logging.falcon_logging.request_reader import FalconRequestReader +from sap.cf_logging.falcon_logging.response_reader import FalconResponseReader + +FALCON_FRAMEWORK_NAME = 'falcon.framework' + + +class LoggingMiddleware: + + def __init__(self, logger='cf.falcon.logger'): + self.logger = logger + + def process_request(self, req, resp): + """Process the request before routing it. + + :param req: - Falcon Request object + :param resp : - Falcon Response object + """ + framework = cf_logging.framework + cid = framework.request_reader.get_correlation_id(req) + framework.context.set('correlation_id', cid, req) + framework.context.set('request_started_at', datetime.utcnow(), req) + req.log = lambda msg, lvl=logging.INFO, extra={}: logging.getLogger( + self.logger).log(lvl, msg, extra=extra.update({REQUEST_KEY: req}) or extra) + + def process_response(self, req, resp, resource, req_succeeded): + """Post-processing of the response (after routing). + + :param req: - Falcon Request object + :param resp : - Falcon Response object + :param resource : - Falcon Resource object to which the request was + routed + :param req_succeeded : - True if no exceptions were raised while + the framework processed and routed the request + """ + cf_logging.framework.context.set( + 'response_sent_at', datetime.utcnow(), req) + extra = {REQUEST_KEY: req, RESPONSE_KEY: resp} + logging.getLogger(self.logger).info('', extra=extra) + + +def init(app, level=defaults.DEFAULT_LOGGING_LEVEL): + """ Initializes logging in JSON format. + + :param app: - Falcon application object + :param level: - valid log level from standard logging package (optional) + """ + if not isinstance(app, falcon.API): + raise TypeError('application should be instance of Falcon API') + + framework = Framework(FALCON_FRAMEWORK_NAME, FalconContext(), + FalconRequestReader(), FalconResponseReader()) + cf_logging.init(framework, level) diff --git a/sap/cf_logging/falcon_logging/context.py b/sap/cf_logging/falcon_logging/context.py new file mode 100644 index 0000000..993f89f --- /dev/null +++ b/sap/cf_logging/falcon_logging/context.py @@ -0,0 +1,17 @@ +""" Falcon 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 + + +class FalconContext(Context): + """ Stores logging context in Falcon's request object""" + + def set(self, key, value, request): + request.context[key] = value + + def get(self, key, request): + return request.context.get(key) diff --git a/sap/cf_logging/falcon_logging/request_reader.py b/sap/cf_logging/falcon_logging/request_reader.py new file mode 100644 index 0000000..9516d00 --- /dev/null +++ b/sap/cf_logging/falcon_logging/request_reader.py @@ -0,0 +1,39 @@ +""" Falcon request reader """ + +import base64 +import binascii +import logging + +from sap.cf_logging import defaults +from sap.cf_logging.core.request_reader import RequestReader + + +class FalconRequestReader(RequestReader): + def get_remote_user(self, request): + remote_user = defaults.UNKNOWN + http_auth = request.get_header('Authorization') + if http_auth and http_auth.startswith('Basic'): + auth_parts = http_auth.split(' ', 1) + if len(auth_parts) == 2: + try: + tokens = base64.b64decode( + auth_parts[1].strip().encode('utf-8')).decode('utf-8') + tokens = tokens.split(":", 1) + except (TypeError, binascii.Error, UnicodeDecodeError) as exc: + logging.debug("Couldn't get username: %s", exc) + return remote_user + if len(tokens) == 2: + remote_user = tokens[0] + return remote_user + + def get_protocol(self, request): + return request.scheme + + def get_content_length(self, request): + return request.content_length + + def get_remote_ip(self, request): + return request.remote_addr + + def get_remote_port(self, request): + return defaults.UNKNOWN diff --git a/sap/cf_logging/falcon_logging/response_reader.py b/sap/cf_logging/falcon_logging/response_reader.py new file mode 100644 index 0000000..023df0e --- /dev/null +++ b/sap/cf_logging/falcon_logging/response_reader.py @@ -0,0 +1,12 @@ +""" Falcon response reader """ +from sap.cf_logging.core.response_reader import ResponseReader + +CONTENT_LENGTH = 'Content-Length' + + +class FalconResponseReader(ResponseReader): + def get_status_code(self, response): + return response.status.split(' ', 1)[0] + + def get_response_size(self, response): + return response.get_header('Content-Length') diff --git a/test-requirements.txt b/test-requirements.txt index 0f13ed9..eca4d46 100644 --- a/test-requirements.txt +++ b/test-requirements.txt @@ -1,4 +1,5 @@ asyncio +falcon Flask sanic; python_version >= '3.5' aiohttp; python_version >= '3.5' diff --git a/tests/test_falcon_logging.py b/tests/test_falcon_logging.py new file mode 100644 index 0000000..0f69022 --- /dev/null +++ b/tests/test_falcon_logging.py @@ -0,0 +1,102 @@ +""" Module that tests the integration of cf_logging with Falcon """ +import logging +import pytest +import falcon +from falcon import testing +from sap import cf_logging +from sap.cf_logging import falcon_logging +from tests.log_schemas import WEB_LOG_SCHEMA, CLI_LOG_SCHEMA +from tests.common_test_params import ( + v_str, v_num, auth_basic, get_web_record_header_fixtures +) +from tests.util import check_log_record, config_root_logger + + +# pylint: disable=protected-access + +@pytest.mark.xfail(raises=TypeError, strict=True) +def test_falcon_requires_valid_app(): + """ Test the init api expects a valid app """ + falcon_logging.init({}) + + +FIXTURE = get_web_record_header_fixtures() +FIXTURE.append(({'Authorization': str(auth_basic('user', 'pass'))}, + {'remote_user': v_str('user')})) + + +class TestResource: + def on_get(self, req, resp): + resp.set_header('Content-Type', 'text/plain') + resp.status = falcon.HTTP_200 + resp.body = 'ok' + + +@pytest.mark.parametrize("headers, expected", FIXTURE) +def test_falcon_request_log(headers, expected): + """ That the expected records are logged by the logging library """ + app = falcon.API(middleware=[ + falcon_logging.LoggingMiddleware() + ]) + app.add_route('/test/path', TestResource()) + + _set_up_falcon_logging(app) + _, stream = config_root_logger('cf.falcon.logger') + + client = testing.TestClient(app) + _check_expected_response( + client.simulate_get('/test/path', headers=headers)) + assert check_log_record(stream, WEB_LOG_SCHEMA, expected) == {} + + +def test_web_log(): + """ That the custom properties are logged """ + _user_logging({}, {'myprop': 'myval'}, {'myprop': 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')} + ) + + +# Helper functions +def _set_up_falcon_logging(app, level=logging.DEBUG): + cf_logging._setup_done = False + falcon_logging.init(app, level) + + +class TestUserResource: + + def __init__(self, extra, expected): + self.extra = extra + self.expected = expected + + def on_get(self, req, resp): + _, stream = config_root_logger('user.logging') + req.log('in route headers', extra=self.extra) + assert check_log_record(stream, CLI_LOG_SCHEMA, self.expected) == {} + + resp.set_header('Content-Type', 'text/plain') + resp.status = falcon.HTTP_200 + resp.body = 'ok' + + +def _user_logging(headers, extra, expected): + app = falcon.API(middleware=[ + falcon_logging.LoggingMiddleware() + ]) + app.add_route('/test/user/logging', TestUserResource(extra, expected)) + _set_up_falcon_logging(app) + client = testing.TestClient(app) + _check_expected_response(client.simulate_get('/test/user/logging', + headers=headers)) + + +def _check_expected_response(response, status_code=200, body='ok'): + assert response.status_code == status_code + if body is not None: + assert response.text == body