Properly format log record & report logged extras to rollbar

This change passes the log record through the configured formatter, if
any, and reports any non blocklisted logging record keys as extra data.
This allows supporting Python logging's `extra` keyword argument which
sets additional properties on the log record.

Author: terencehonles

rollbar/logger.py

@@ -32,6 +32,18 @@
     _checkLevel = lambda lvl: lvl
 
 
+EXCLUDE_RECORD_KEYS = {
+    # Attributes that are disallowed in `logging.Logger.makeRecord`
+    'asctime',
+    'message',
+    # Attributes that are used internally by pyrollbar
+    'extra_data',
+    'payload_data',
+    'request',
+    *vars(logging.makeLogRecord({})).keys(),
+}
+
+
 def resolve_logging_types(obj):
     if isinstance(obj, (dict, ConvertingDict)):
         return {k: resolve_logging_types(v) for k, v in obj.items()}
@@ -116,9 +128,10 @@ def emit(self, record):
                 'thread': record.thread,
                 'threadName': record.threadName
             }
-        }
-
-        extra_data.update(getattr(record, 'extra_data', {}))
+        } | {  # include any extras
+            k: v for k, v in vars(record).items()
+            if k not in EXCLUDE_RECORD_KEYS
+        } | getattr(record, 'extra_data', {})  # include historical extra_data
 
         payload_data = getattr(record, 'payload_data', {})
 
@@ -133,18 +146,25 @@ def emit(self, record):
         # load the request
         request = getattr(record, "request", None) or rollbar.get_request()
 
+        # Rather than copy the log record and disable exception and stack trace
+        # formatting, this does the same steps to prepare the log record
+        # as `logging.Formatter.format` does before calling
+        # `logging.Formatter.formatMessage`.
+        formatter = self.formatter or logging._defaultFormatter
+        record.message = record.getMessage()
+        if formatter.usesTime():
+            record.asctime = formatter.formatTime(record, formatter.datefmt)
+
+        message = formatter.formatMessage(record)
+
         uuid = None
         try:
             # when not in an exception handler, exc_info == (None, None, None)
             if exc_info and exc_info[0]:
                 if record.msg:
                     message_template = {
                         'body': {
-                            'trace': {
-                                'exception': {
-                                    'description': record.getMessage()
-                                }
-                            }
+                            'trace': {'exception': {'description': message}}
                         }
                     }
                     payload_data = rollbar.dict_merge(
@@ -156,7 +176,7 @@ def emit(self, record):
                                                extra_data=extra_data,
                                                payload_data=payload_data)
             else:
-                uuid = rollbar.report_message(record.getMessage(),
+                uuid = rollbar.report_message(message,
                                               level=level,
                                               request=request,
                                               extra_data=extra_data,

rollbar/test/test_loghandler.py

@@ -26,22 +26,20 @@ class LogHandlerTest(BaseTest):
     def setUp(self):
         rollbar._initialized = False
         rollbar.SETTINGS = copy.deepcopy(_default_settings)
-
-    def _create_logger(self):
-        logger = logging.getLogger(__name__)
-        logger.setLevel(logging.DEBUG)
+        self.logger = logging.getLogger(__name__)
+        self.logger.setLevel(logging.DEBUG)
 
         self.rollbar_handler = RollbarHandler(_test_access_token, _test_environment)
         self.rollbar_handler.setLevel(logging.WARNING)
 
-        logger.addHandler(self.rollbar_handler)
+        self.logger.addHandler(self.rollbar_handler)
 
-        return logger
+    def tearDown(self):
+        self.logger.removeHandler(self.rollbar_handler)
 
     @mock.patch('rollbar.send_payload')
     def test_message_gets_formatted(self, send_payload):
-        logger = self._create_logger()
-        logger.warning("Hello %d %s", 1, 'world')
+        self.logger.warning("Hello %d %s", 1, 'world')
 
         payload = send_payload.call_args[0][0]
 
@@ -53,22 +51,20 @@ def test_message_gets_formatted(self, send_payload):
 
     @mock.patch('rollbar.send_payload')
     def test_string_or_int_level(self, send_payload):
-        logger = self._create_logger()
-        logger.setLevel(logging.ERROR)
+        self.logger.setLevel(logging.ERROR)
         self.rollbar_handler.setLevel('WARNING')
-        logger.error("I am an error")
+        self.logger.error("I am an error")
 
         payload = send_payload.call_args[0][0]
 
         self.assertEqual(payload['data']['level'], 'error')
 
         self.rollbar_handler.setLevel(logging.WARNING)
-        logger.error("I am an error")
+        self.logger.error("I am an error")
 
         self.assertEqual(payload['data']['level'], 'error')
 
     def test_request_is_get_from_log_record_if_present(self):
-        logger = self._create_logger()
         # Request objects vary depending on python frameworks or packages.
         # Using a dictionary for this test is enough.
         request = {"fake": "request", "for":  "testing purporse"}
@@ -77,15 +73,15 @@ def test_request_is_get_from_log_record_if_present(self):
         # just need to be sure that proper rollbar function is called
         # with passed request as argument.
         with mock.patch("rollbar.report_message") as report_message_mock:
-            logger.warning("Warning message", extra={"request": request})
+            self.logger.warning("Warning message", extra={"request": request})
             self.assertEqual(report_message_mock.call_args[1]["request"], request)
 
         # if you call logger.exception outside of an exception
         # handler, it shouldn't try to report exc_info, since it
         # won't have any
         with mock.patch("rollbar.report_exc_info") as report_exc_info:
             with mock.patch("rollbar.report_message") as report_message_mock:
-                logger.exception("Exception message", extra={"request": request})
+                self.logger.exception("Exception message", extra={"request": request})
                 report_exc_info.assert_not_called()
                 self.assertEqual(report_message_mock.call_args[1]["request"], request)
 
@@ -94,14 +90,12 @@ def test_request_is_get_from_log_record_if_present(self):
                 try:
                     raise Exception()
                 except:
-                    logger.exception("Exception message", extra={"request": request})
+                    self.logger.exception("Exception message", extra={"request": request})
                     self.assertEqual(report_exc_info.call_args[1]["request"], request)
                     report_message_mock.assert_not_called()
 
     @mock.patch('rollbar.send_payload')
     def test_nested_exception_trace_chain(self, send_payload):
-        logger = self._create_logger()
-
         def _raise_context():
             bar_local = 'bar'
             raise CauseException('bar')
@@ -120,7 +114,7 @@ def _raise_ex():
                     setattr(e, '__context__', context)  # PEP-3134
                     raise e
                 except:
-                    logger.exception("Bad time")
+                    self.logger.exception("Bad time")
 
         _raise_ex()
 
@@ -139,8 +133,6 @@ def _raise_ex():
 
     @mock.patch('rollbar.send_payload')
     def test_not_nested_exception_trace_chain(self, send_payload):
-        logger = self._create_logger()
-
         def _raise_context():
             bar_local = 'bar'
             raise CauseException('bar')
@@ -149,7 +141,7 @@ def _raise_ex():
             try:
                 _raise_context()
             except:
-                logger.exception("Bad time")
+                self.logger.exception("Bad time")
 
         _raise_ex()
 
@@ -165,3 +157,34 @@ def _raise_ex():
             self.assertEqual('Bad time', payload['data']['custom']['exception']['description'])
         if trace is not None:
             self.assertEqual('Bad time', trace['exception']['description'])
+
+    @mock.patch('rollbar.send_payload')
+    def test_logging_extra(self, send_payload):
+        self.logger.error("Test error", extra=dict(test_attribute=1, test_other='test'))
+
+        payload = send_payload.call_args[0][0]
+        self.assertEqual(payload['data']['body']['message'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['body']['message'].get('test_other'), 'test')
+        self.assertEqual(payload['data']['custom'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['custom'].get('test_other'), 'test')
+
+    @mock.patch('rollbar.send_payload')
+    def test_logging_extra_data(self, send_payload):
+        self.logger.error(
+            "Test error",
+            extra=dict(extra_data=dict(test_attribute=1, test_other='test')))
+
+        payload = send_payload.call_args[0][0]
+        self.assertEqual(payload['data']['body']['message'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['body']['message'].get('test_other'), 'test')
+        self.assertEqual(payload['data']['custom'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['custom'].get('test_other'), 'test')
+
+    @mock.patch('rollbar.send_payload')
+    def test_log_formatting(self, send_payload):
+        self.rollbar_handler.formatter = logging.Formatter(
+            '%(test_other)s[%(test_attribute)s]: %(message)s'
+        )
+        self.logger.error("Test error", extra=dict(test_attribute=1, test_other='test'))
+        payload = send_payload.call_args[0][0]
+        self.assertEqual(payload['data']['body']['message']['body'], 'test[1]: Test error')