Logging Attributes

newrelic/api/application.py

@@ -22,7 +22,6 @@
 
 
 class Application(object):
-
     _lock = threading.Lock()
     _instances = {}
 
@@ -162,9 +161,11 @@ def record_transaction(self, data):
         if self.active:
             self._agent.record_transaction(self._name, data)
 
-    def record_log_event(self, message, level=None, timestamp=None, priority=None):
+    def record_log_event(self, message, level=None, timestamp=None, attributes=None, priority=None):
         if self.active:
-            self._agent.record_log_event(self._name, message, level, timestamp, priority=priority)
+            self._agent.record_log_event(
+                self._name, message, level, timestamp, attributes=attributes, priority=priority
+            )
 
     def normalize_name(self, name, rule_type="url"):
         if self.active:

newrelic/api/log.py

@@ -21,9 +21,11 @@
 from newrelic.api.time_trace import get_linking_metadata
 from newrelic.api.transaction import current_transaction, record_log_event
 from newrelic.common import agent_http
+from newrelic.common.encoding_utils import json_encode
 from newrelic.common.object_names import parse_exc_info
 from newrelic.core.attribute import truncate
 from newrelic.core.config import global_settings, is_expected_error
+from newrelic.packages import six
 
 
 def format_exc_info(exc_info):
@@ -42,8 +44,30 @@ def format_exc_info(exc_info):
     return formatted
 
 
+def safe_json_encode(obj, ignore_string_types=False, **kwargs):
+    # Performs the same operation as json_encode but replaces unserializable objects with a string containing their class name.
+    # If ignore_string_types is True, do not encode string types further.
+    # Currently used for safely encoding logging attributes.
+
+    if ignore_string_types and isinstance(obj, (six.string_types, six.binary_type)):
+        return obj
+
+    # Attempt to run through JSON serialization
+    try:
+        return json_encode(obj, **kwargs)
+    except Exception:
+        pass
+
+    # If JSON serialization fails then return a repr
+    try:
+        return repr(obj)
+    except Exception:
+        # If repr fails then default to an unprinatable object name
+        return "<unprintable %s object>" % type(obj).__name__
+
+
 class NewRelicContextFormatter(Formatter):
-    DEFAULT_LOG_RECORD_KEYS = frozenset(vars(LogRecord("", 0, "", 0, "", (), None)))
+    DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
 
     def __init__(self, *args, **kwargs):
         super(NewRelicContextFormatter, self).__init__()
@@ -76,17 +100,12 @@ def log_record_to_dict(cls, record):
         return output
 
     def format(self, record):
-        def safe_str(object, *args, **kwargs):
-            """Convert object to str, catching any errors raised."""
-            try:
-                return str(object, *args, **kwargs)
-            except:
-                return "<unprintable %s object>" % type(object).__name__
-
-        return json.dumps(self.log_record_to_dict(record), default=safe_str, separators=(",", ":"))
+        return json.dumps(self.log_record_to_dict(record), default=safe_json_encode, separators=(",", ":"))
 
 
 class NewRelicLogForwardingHandler(logging.Handler):
+    DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
+
     def emit(self, record):
         try:
             # Avoid getting local log decorated message
@@ -95,10 +114,20 @@ def emit(self, record):
             else:
                 message = record.getMessage()
 
-            record_log_event(message, record.levelname, int(record.created * 1000))
+            attrs = self.filter_record_attributes(record)
+            record_log_event(message, record.levelname, int(record.created * 1000), attributes=attrs)
         except Exception:
             self.handleError(record)
 
+    @classmethod
+    def filter_record_attributes(cls, record):
+        record_attrs = vars(record)
+        DEFAULT_LOG_RECORD_KEYS = cls.DEFAULT_LOG_RECORD_KEYS
+        if len(record_attrs) > len(DEFAULT_LOG_RECORD_KEYS):
+            return {k: v for k, v in six.iteritems(vars(record)) if k not in DEFAULT_LOG_RECORD_KEYS}
+        else:
+            return None
+
 
 class NewRelicLogHandler(logging.Handler):
     """
@@ -126,8 +155,8 @@ def __init__(
             "The contributed NewRelicLogHandler has been superseded by automatic instrumentation for "
             "logging in the standard lib. If for some reason you need to manually configure a handler, "
             "please use newrelic.api.log.NewRelicLogForwardingHandler to take advantage of all the "
-            "features included in application log forwarding such as proper batching.", 
-            DeprecationWarning
+            "features included in application log forwarding such as proper batching.",
+            DeprecationWarning,
         )
         super(NewRelicLogHandler, self).__init__(level=level)
         self.license_key = license_key or self.settings.license_key

newrelic/api/transaction.py

@@ -54,6 +54,7 @@
     create_attributes,
     create_user_attributes,
     process_user_attribute,
+    resolve_logging_context_attributes,
     truncate,
 )
 from newrelic.core.attribute_filter import (
@@ -1524,7 +1525,7 @@ def set_transaction_name(self, name, group=None, priority=None):
         self._group = group
         self._name = name
 
-    def record_log_event(self, message, level=None, timestamp=None, priority=None):
+    def record_log_event(self, message, level=None, timestamp=None, attributes=None, priority=None):
         settings = self.settings
         if not (
             settings
@@ -1537,18 +1538,62 @@ def record_log_event(self, message, level=None, timestamp=None, priority=None):
 
         timestamp = timestamp if timestamp is not None else time.time()
         level = str(level) if level is not None else "UNKNOWN"
+        context_attributes = attributes  # Name reassigned for clarity
 
-        if not message or message.isspace():
-            _logger.debug("record_log_event called where message was missing. No log event will be sent.")
-            return
+        # Unpack message and attributes from dict inputs
+        if isinstance(message, dict):
+            message_attributes = {k: v for k, v in message.items() if k != "message"}
+            message = message.get("message", "")
+        else:
+            message_attributes = None
+
+        if message is not None:
+            # Coerce message into a string type
+            if not isinstance(message, six.string_types):
+                try:
+                    message = str(message)
+                except Exception:
+                    # Exit early for invalid message type after unpacking
+                    _logger.debug(
+                        "record_log_event called where message could not be converted to a string type. No log event will be sent."
+                    )
+                    return
+
+            # Truncate the now unpacked and string converted message
+            message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
+
+        # Collect attributes from linking metadata, context data, and message attributes
+        collected_attributes = {}
+        if settings and settings.application_logging.forwarding.context_data.enabled:
+            if context_attributes:
+                context_attributes = resolve_logging_context_attributes(
+                    context_attributes, settings.attribute_filter, "context."
+                )
+                if context_attributes:
+                    collected_attributes.update(context_attributes)
+
+            if message_attributes:
+                message_attributes = resolve_logging_context_attributes(
+                    message_attributes, settings.attribute_filter, "message."
+                )
+                if message_attributes:
+                    collected_attributes.update(message_attributes)
+
+            # Exit early if no message or attributes found after filtering
+            if (not message or message.isspace()) and not context_attributes and not message_attributes:
+                _logger.debug(
+                    "record_log_event called where no message and no attributes were found. No log event will be sent."
+                )
+                return
 
-        message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
+        # Finally, add in linking attributes after checking that there is a valid message or at least 1 attribute
+        collected_attributes.update(get_linking_metadata())
 
         event = LogEventNode(
             timestamp=timestamp,
             level=level,
             message=message,
-            attributes=get_linking_metadata(),
+            attributes=collected_attributes,
         )
 
         self._log_events.add(event, priority=priority)
@@ -2062,7 +2107,7 @@ def record_ml_event(event_type, params, application=None):
         application.record_ml_event(event_type, params)
 
 
-def record_log_event(message, level=None, timestamp=None, application=None, priority=None):
+def record_log_event(message, level=None, timestamp=None, attributes=None, application=None, priority=None):
     """Record a log event.
 
     Args:
@@ -2073,12 +2118,12 @@ def record_log_event(message, level=None, timestamp=None, application=None, prio
     if application is None:
         transaction = current_transaction()
         if transaction:
-            transaction.record_log_event(message, level, timestamp)
+            transaction.record_log_event(message, level, timestamp, attributes=attributes)
         else:
             application = application_instance(activate=False)
 
             if application and application.enabled:
-                application.record_log_event(message, level, timestamp, priority=priority)
+                application.record_log_event(message, level, timestamp, attributes=attributes, priority=priority)
             else:
                 _logger.debug(
                     "record_log_event has been called but no transaction or application was running. As a result, "
@@ -2089,7 +2134,7 @@ def record_log_event(message, level=None, timestamp=None, application=None, prio
                     timestamp,
                 )
     elif application.enabled:
-        application.record_log_event(message, level, timestamp, priority=priority)
+        application.record_log_event(message, level, timestamp, attributes=attributes, priority=priority)
 
 
 def accept_distributed_trace_payload(payload, transport_type="HTTP"):