Merge pull request #63 from geoadmin/feat-pb-931-python-exception-logging

PB-931 Change behavior of exc_text and stack_info - #major

Author: schtibe

README.md

@@ -17,7 +17,7 @@ All features can be fully configured from the configuration file.
 
 **NOTE:** only python 3 is supported
 
-:warning: **Version 3.x.x BREAKING CHANGES** see [Breaking Changes](#version-3xx-breaking-changes)
+:warning: **Version 5.x.x BREAKING CHANGES** see [Breaking Changes](#version-5xx-breaking-changes)
 
 ## Table of content
 
@@ -67,7 +67,9 @@ All features can be fully configured from the configuration file.
   - [Case 7. Add all Log Extra as Dictionary to the Standard Formatter (including Django log extra)](#case-7-add-all-log-extra-as-dictionary-to-the-standard-formatter-including-django-log-extra)
   - [Case 8. Add Specific Log Extra to the Standard Formatter](#case-8-add-specific-log-extra-to-the-standard-formatter)
   - [Case 9. Django add request info to all log records](#case-9-django-add-request-info-to-all-log-records)
+  - [Case 10. Add stack traces to log records](#case-10-add-stack-traces-to-log-records)
 - [Breaking Changes](#breaking-changes)
+  - [Version 5.x.x Breaking Changes](#version-5xx-breaking-changes)
   - [Version 4.x.x Breaking Changes](#version-4xx-breaking-changes)
   - [Version 3.x.x Breaking Changes](#version-3xx-breaking-changes)
   - [Version 2.x.x Breaking Changes](#version-2xx-breaking-changes)
@@ -273,7 +275,7 @@ For more information on Pyramid Tweens see [Registering Tween](https://docs.pylo
 
 ## JSON Formatter
 
-**JsonFormatter** is a python logging formatter that transform the log output into a json object.
+**JsonFormatter** is a python logging formatter that transforms the log output into a json object.
 
 JSON log format is quite useful especially when the logs are sent to **LogStash**.
 
@@ -1368,8 +1370,46 @@ handlers:
       - request_fields
 ```
 
+### Case 10. Add stack traces to log records
+
+If you want to embed the stack trace of either an Exception or a log entry in general, you can do so with following additions to the logging call:
+
+```python
+import sys
+
+logger.debug('My log with stack info', stack_info=True)
+logger.critical('Exception happened', exc_info=sys.exc_info())
+```
+
+Or you simply call `logger.exception('Your message')` which automatically adds the exc_info. However this one is logging as in level `ERROR` and not `CRITICAL`.
+
+This will make the stack info available for the formatter. It can be used for instance like follows:
+
+```yaml
+[...]
+formatters:
+  json:
+    (): logging_utilities.formatters.json_formatter.JsonFormatter
+    fmt:
+      error:
+        stack_trace: exc_text
+      stack_info: stack_info
+      time: asctime
+      level: levelname
+      logger: name
+      module: module
+      message: message
+      request:
+        path: request.path
+        method: request.method
+```
+
 ## Breaking Changes
 
+### Version 5.x.x Breaking Changes
+
+Previously, the fields `exc_text` and `stack_info` were always added to the log message if they existed. This behavior is slightly changed: instead of adding them to the message in any case, they are added to the record so that they can be configured via the `fmt` field in the logging configuration as described in [#case-10-add-stack-traces-to-log-records].
+
 ### Version 4.x.x Breaking Changes
 
 From version 3.x.x to version 4.x.x there is the following breaking change:

logging_utilities/formatters/json_formatter.py

@@ -343,21 +343,19 @@ def format(self, record):
         if self.add_always_extra:
             extra = self._get_extra_attrs(record)
 
-        message = self.formatMessage(record)
-
-        if self.add_always_extra:
-            self._add_extra_to_message(extra, message)
-
         if record.exc_info:
             # Cache the traceback text to avoid converting it multiple times
             # (it's constant anyway)
             if not record.exc_text:
                 record.exc_text = self.formatException(record.exc_info)
-        if record.exc_text:
-            message['exc_text'] = record.exc_text
 
         if record.stack_info:
-            message['stack_info'] = self.formatStack(record.stack_info)
+            record.stack_info = self.formatStack(record.stack_info)
+
+        message = self.formatMessage(record)
+
+        if self.add_always_extra:
+            self._add_extra_to_message(extra, message)
 
         # When adding all extras, to avoid crash when a log message adds an extra with a non
         # serializable object, we add a default serializer.

tests/test_json_formatter.py

@@ -18,6 +18,7 @@
     dictionary = OrderedDict
 
 
+# pylint: disable=too-many-public-methods
 class BasicJsonFormatterTest(unittest.TestCase):
     maxDiff = None
 
@@ -378,11 +379,8 @@ def test_stack_info(self):
             logger = logging.getLogger('test_formatter')
             self._configure_logger(
                 logger,
-                fmt=dictionary([
-                    ('levelname', 'levelname'),
-                    ('name', 'name'),
-                    ('message', 'message'),
-                ])
+                fmt=dictionary([('levelname', 'levelname'), ('name', 'name'),
+                                ('message', 'message'), ('stack_info', 'stack_info')])
             )
             logger.info('Message with stack info', stack_info=True)
         message = json.loads(ctx.output[0], object_pairs_hook=dictionary)
@@ -787,3 +785,79 @@ def test_missing_attribute(self):
                 ("message", "Composed message without extra"),
             ])
         )
+
+    def test_exc_info_without_configuration(self):
+        """
+        Test that the exc_text doesn't appear if it's not configured
+        in the logger, even though the logging call records it
+        """
+        with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx:
+            logger = logging.getLogger('test_formatter')
+            self._configure_logger(
+                logger,
+                fmt=dictionary([
+                    ('level', 'levelname'),
+                    ('request', ['request.path', 'request.method']),
+                    ('message', 'message'),
+                ]),
+                remove_empty=True,
+                ignore_missing=True
+            )
+
+            try:
+                raise Exception("Error occurred")
+            except Exception as err:  # pylint: disable=broad-except
+                logger.critical(
+                    str(err),
+                    exc_info=sys.exc_info(),
+                    extra={'request': {
+                        'path': '/my/path', 'method': 'GET', 'scheme': 'https'
+                    }}
+                )
+
+        self.assertDictEqual(
+            json.loads(ctx.output[0], object_pairs_hook=dictionary),
+            dictionary([
+                ("level", "CRITICAL"),
+                ("request", ["/my/path", "GET"]),
+                ("message", "Error occurred"),  # no exc_text because it wasn't configured
+            ])
+        )
+
+    def test_stack_info_without_configuration(self):
+        """
+        Test that the stack_info doesn't appear in the record when it's
+        not configured, even though the log call records it
+        """
+        with self.assertLogs('test_formatter', level=logging.DEBUG) as ctx:
+            logger = logging.getLogger('test_formatter')
+            self._configure_logger(
+                logger,
+                fmt=dictionary([
+                    ('level', 'levelname'),
+                    ('request', ['request.path', 'request.method']),
+                    ('message', 'message'),
+                ]),
+                remove_empty=True,
+                ignore_missing=True
+            )
+
+            logger.info(
+                "Stack isn't wished for here",
+                exc_info=sys.exc_info(),
+                extra={'request': {
+                    'path': '/my/path', 'method': 'GET', 'scheme': 'https'
+                }},
+                # record the stack_info
+                stack_info=True
+            )
+
+        self.assertDictEqual(
+            json.loads(ctx.output[0], object_pairs_hook=dictionary),
+            dictionary([
+                ("level", "INFO"),
+                ("request", ["/my/path", "GET"]),
+                ("message",
+                 "Stack isn't wished for here"),  # no stack_info because it wasn't configured
+            ])
+        )