Feature log exception stacktrace (#28)

* Add logging for stacktrace of logger exceptions
* Remove log and exception methods from falcon request
* Adapt README to falcon logging changes
* Apply PR comment changes

Author: georgi-bozhinov

README.rst

@@ -121,12 +121,13 @@ Falcon
 
    import falcon
    from sap.cf_logging import falcon_logging
+   from sap.cf_logging.core.constants import REQUEST_KEY
 
 
    class Resource:
        def on_get(self, req, resp):
-           # Use the log() method of the req object to log additional messages
-           req.log('Resource requested')
+           extra = {REQUEST_KEY: req}
+           logging.getLogger('my.logger').log('Resource requested', extra=extra)
            resp.media = {'name': 'Cloud Foundry'}
 
 
@@ -136,8 +137,6 @@ Falcon
    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/constants.py

@@ -5,3 +5,5 @@
 LOG_SENSITIVE_CONNECTION_DATA = 'LOG_SENSITIVE_CONNECTION_DATA'
 LOG_REMOTE_USER = 'LOG_REMOTE_USER'
 LOG_REFERER = 'LOG_REFERER'
+
+STACKTRACE_MAX_SIZE = 55 * 1024

sap/cf_logging/falcon_logging/__init__.py

@@ -15,13 +15,13 @@
 FALCON_FRAMEWORK_NAME = 'falcon.framework'
 
 
-class LoggingMiddleware:
+class LoggingMiddleware(object):
     """ Falcon logging middleware """
 
     def __init__(self, logger_name='cf.falcon.logger'):
         self._logger_name = logger_name
 
-    def process_request(self, request, response): # pylint: disable=unused-argument
+    def process_request(self, request, response): # pylint: disable=unused-argument,no-self-use
         """Process the request before routing it.
 
         :param request: - Falcon Request object
@@ -31,8 +31,6 @@ def process_request(self, request, response): # pylint: disable=unused-argument
         cid = framework.request_reader.get_correlation_id(request)
         framework.context.set_correlation_id(cid, request)
         framework.context.set('request_started_at', datetime.utcnow(), request)
-        request.log = lambda msg, lvl=logging.INFO, extra={}: logging.getLogger(
-            self._logger_name).log(lvl, msg, extra=extra.update({REQUEST_KEY: request}) or extra)
 
     def process_response(self, request, response, resource, req_succeeded): # pylint: disable=unused-argument
         """Post-processing of the response (after routing).

sap/cf_logging/formatters/stacktrace_formatter.py

@@ -0,0 +1,51 @@
+"""
+Module for formatting utilities for stacktrace
+generated by user logging.exception call
+"""
+import re
+
+from sap.cf_logging.core import constants
+
+
+def format_stacktrace(stacktrace):
+    """
+    Removes newline and tab characters
+    Truncates stacktrace to maximum size
+
+    :param stacktrace: string representation of a stacktrace
+    """
+    if not isinstance(stacktrace, str):
+        return ''
+
+    stacktrace = re.sub('\n|\t', '  ', stacktrace)
+
+    if len(stacktrace) <= constants.STACKTRACE_MAX_SIZE:
+        return stacktrace
+
+    stacktrace_beginning = _stacktrace_beginning(
+        stacktrace, constants.STACKTRACE_MAX_SIZE // 3
+    )
+
+    stacktrace_end = _stacktrace_end(
+        stacktrace, (constants.STACKTRACE_MAX_SIZE // 3) * 2
+    )
+
+    new_stacktrace = "-------- STACK TRACE TRUNCATED --------" + stacktrace_beginning +\
+                        "-------- OMITTED --------" + stacktrace_end
+
+    return new_stacktrace
+
+def _stacktrace_beginning(stacktrace, size):
+    """ Gets the first `size` bytes of the stacktrace """
+    if len(stacktrace) <= size:
+        return stacktrace
+
+    return stacktrace[:size]
+
+def _stacktrace_end(stacktrace, size):
+    """ Gets the last `size` bytes of the stacktrace """
+    stacktrace_length = len(stacktrace)
+    if stacktrace_length <= size:
+        return stacktrace
+
+    return stacktrace[:-(stacktrace_length-size)]

sap/cf_logging/record/simple_log_record.py

@@ -1,11 +1,15 @@
 """ Module SimpleLogRecord """
 import logging
+import traceback
+
 from datetime import datetime
 from sap.cf_logging import defaults
 from sap.cf_logging.core.constants import REQUEST_KEY, RESPONSE_KEY
 from sap.cf_logging.record import application_info
 from sap.cf_logging.record import util
 
+from sap.cf_logging.formatters.stacktrace_formatter import format_stacktrace
+
 _SKIP_ATTRIBUTES = ["type", "written_at", "written_ts", "correlation_id", "remote_user", "referer",
                     "x_forwarded_for", "protocol", "method", "remote_ip", "request_size_b",
                     "remote_host", "remote_port", "request_received_at", "direction",
@@ -63,5 +67,9 @@ def format(self):
             'msg': self.getMessage(),
         })
 
+        if self.levelno == logging.ERROR:
+            stacktrace = ''.join(traceback.format_exception(*self.exc_info))
+            record['stacktrace'] = format_stacktrace(stacktrace)
+
         record.update(self.extra)
         return record

tests/log_schemas.py

@@ -26,7 +26,7 @@
     'written_at': u.iso_datetime(),
     'written_ts': u.pos_num(),
     'msg': u.string(u.WORD),
-    'component_type': u.string(r'^application$')
+    'component_type': u.string(r'^application$'),
 })
 
 WEB_LOG_SCHEMA = u.extend(CF_ATTRIBUTES_SCHEMA, {

tests/test_falcon_logging.py

@@ -6,11 +6,17 @@
 from falcon_auth import FalconAuthMiddleware, BasicAuthBackend
 from sap import cf_logging
 from sap.cf_logging import falcon_logging
+from sap.cf_logging.core.constants import REQUEST_KEY
 from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA
 from tests.common_test_params import (
     v_str, auth_basic, get_web_record_header_fixtures
 )
-from tests.util import check_log_record, config_root_logger, enable_sensitive_fields_logging
+from tests.util import (
+    check_log_record,
+    config_root_logger,
+    enable_sensitive_fields_logging,
+    config_logger
+)
 
 
 # pylint: disable=protected-access, missing-docstring,too-few-public-methods
@@ -101,16 +107,16 @@ def _set_up_falcon_logging(app, *args):
     falcon_logging.init(app, logging.DEBUG, *args)
 
 
-class UserResourceRoute:
-
+class UserResourceRoute(object):
     def __init__(self, extra, expected):
         self.extra = extra
         self.expected = expected
+        self.logger, self.stream = config_logger('user.logging')
 
     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, JOB_LOG_SCHEMA, self.expected) == {}
+        self.extra.update({REQUEST_KEY: req})
+        self.logger.log(logging.INFO, 'in route headers', extra=self.extra)
+        assert check_log_record(self.stream, JOB_LOG_SCHEMA, self.expected) == {}
 
         resp.set_header('Content-Type', 'text/plain')
         resp.status = falcon.HTTP_200

tests/test_flask_logging.py

@@ -7,7 +7,11 @@
 from sap.cf_logging import flask_logging
 from tests.log_schemas import WEB_LOG_SCHEMA, JOB_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, enable_sensitive_fields_logging
+from tests.util import (
+    check_log_record,
+    enable_sensitive_fields_logging,
+    config_root_logger,
+)
 
 
 # pylint: disable=protected-access
@@ -26,6 +30,7 @@ def test_flask_requires_valid_app():
 
 @pytest.fixture(autouse=True)
 def before_each():
+    # pylint: disable=duplicate-code
     """ enable all fields to be logged """
     enable_sensitive_fields_logging()
     yield

tests/test_job_logging.py

@@ -46,6 +46,23 @@ def test_set_correlation_id():
     assert log_json['correlation_id'] == correlation_id
     assert cf_logging.FRAMEWORK.context.get_correlation_id() == correlation_id
 
+
+def test_exception_stacktrace():
+    """ Test exception stacktrace is logged """
+    cf_logging.init(level=logging.DEBUG)
+    logger, stream = config_root_logger('cli.test')
+
+    try:
+        return 1 / 0
+    except ZeroDivisionError:
+        logger.exception('zero division error')
+        log_json = JSONDecoder().decode(stream.getvalue())
+        _, error = JsonValidator(JOB_LOG_SCHEMA).validate(log_json)
+
+        assert error == {}
+        assert 'ZeroDivisionError' in str(log_json['stacktrace'])
+
+
 def test_thread_safety():
     """ test context keeps separate correlation ID per thread """
     class _SampleThread(threading.Thread):

tests/test_sanic_logging.py

@@ -9,7 +9,11 @@
 from tests.log_schemas import WEB_LOG_SCHEMA, JOB_LOG_SCHEMA
 from tests.common_test_params import v_str, v_num, get_web_record_header_fixtures
 from tests.schema_util import extend
-from tests.util import check_log_record, config_logger, enable_sensitive_fields_logging
+from tests.util import (
+    check_log_record,
+    config_logger,
+    enable_sensitive_fields_logging,
+)
 
 
 # pylint: disable=protected-access
@@ -22,12 +26,14 @@ def test_sanic_requires_valid_app():
 FIXTURE = get_web_record_header_fixtures()
 FIXTURE.append(({'no-content-length': '1'}, {'response_size_b': v_num(-1)}))
 
+
 @pytest.fixture(autouse=True)
 def before_each():
     """ enable all fields to be logged """
     enable_sensitive_fields_logging()
     yield
 
+
 @pytest.mark.parametrize("headers, expected", FIXTURE)
 def test_sanic_request_log(headers, expected):
     """ Test that the JSON logs contain the expected properties based on the
@@ -45,7 +51,8 @@ async def _headers_route(request):
     _, stream = config_logger('cf.sanic.logger')
 
     client = app.test_client
-    _check_expected_response(client.get('/test/path', headers=headers)[1], 200, 'ok')
+    _check_expected_response(client.get(
+        '/test/path', headers=headers)[1], 200, 'ok')
     assert check_log_record(stream, WEB_LOG_SCHEMA, expected) == {}