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,6 +146,15 @@ 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 = record.getMessage()
+        if formatter.usesTime():
+            record.asctime = formatter.formatTime(record, formatter.datefmt)
+
         uuid = None
         try:
             # when not in an exception handler, exc_info == (None, None, None)
@@ -142,7 +164,9 @@ def emit(self, record):
                         'body': {
                             'trace': {
                                 'exception': {
-                                    'description': record.getMessage()
+                                    'description': formatter.formatMessage(
+                                        record
+                                    )
                                 }
                             }
                         }
@@ -156,7 +180,7 @@ def emit(self, record):
                                                extra_data=extra_data,
                                                payload_data=payload_data)
             else:
-                uuid = rollbar.report_message(record.getMessage(),
+                uuid = rollbar.report_message(formatter.formatMessage(record),
                                               level=level,
                                               request=request,
                                               extra_data=extra_data,

rollbar/test/test_loghandler.py

@@ -165,3 +165,21 @@ 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_custom_extra(self, send_payload):
+        logger = self._create_logger()
+        logger.error("Test error", extra=dict(test_attribute=1, test_other='test'))
+
+        payload = send_payload.call_args[0][0]
+        self.assertEqual(payload['data']['body'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['body'].get('test_other'), 'test')
+
+    @mock.patch('rollbar.send_payload')
+    def test_logging_extra_data(self, send_payload):
+        logger = self._create_logger()
+        logger.error("Test error", extra_data=dict(test_attribute=1, test_other='test'))
+
+        payload = send_payload.call_args[0][0]
+        self.assertEqual(payload['data']['body'].get('test_attribute'), 1)
+        self.assertEqual(payload['data']['body'].get('test_other'), 'test')