Add support for Falcon web framework

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
 ^^^^^^^
 

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):

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)

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)

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

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')

test-requirements.txt

@@ -1,4 +1,5 @@
 asyncio
+falcon
 Flask
 sanic; python_version >= '3.5'
 aiohttp; python_version >= '3.5'

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