Add Dictionary Log Message Support (#1014)

* Add tests for logging's json logging

* Upgrade record_log_event to handle dict logging

* Update logging to capture dict messages

* Add attributes for dict log messages

* Implementation of JSON message filtering

* Correct attributes only log behavior

* Testing for logging attributes

* Add logging context test for py2

* Logically separate attribute tests

* Clean out imports

* Fix failing tests

* Remove logging instrumentation changes for new PR

* Add test for record log event edge cases

* Update record_log_event for code review

* Fix truncation

* Move safe_json_encode back to api.log as it's unused elsewhere

* Black formatting

* Add missing import

* Fixup warning message

---------

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

newrelic/api/log.py

@@ -21,7 +21,7 @@
 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 safe_json_encode
+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
@@ -44,6 +44,28 @@ 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(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
 

newrelic/api/transaction.py

@@ -44,7 +44,6 @@
     json_decode,
     json_encode,
     obfuscate,
-    safe_json_encode,
     snake_case,
 )
 from newrelic.core.attribute import (
@@ -1539,18 +1538,56 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=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
 
-        message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
+        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)
 
-        collected_attributes = get_linking_metadata()
-        if attributes and (settings and settings.application_logging.forwarding.context_data.enabled):
-            context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.")
+        # 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:
-                collected_attributes.update(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
+
+        # 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,

newrelic/common/encoding_utils.py

@@ -113,28 +113,6 @@ def json_decode(s, **kwargs):
     return json.loads(s, **kwargs)
 
 
-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__
-
-
 # Functions for obfuscating/deobfuscating text string based on an XOR
 # cipher.
 

newrelic/core/application.py

@@ -943,13 +943,12 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=None,
         if not self._active_session:
             return
 
-        if message:
-            with self._stats_custom_lock:
-                event = self._stats_engine.record_log_event(
-                    message, level, timestamp, attributes=attributes, priority=priority
-                )
-                if event:
-                    self._global_events_account += 1
+        with self._stats_custom_lock:
+            event = self._stats_engine.record_log_event(
+                message, level, timestamp, attributes=attributes, priority=priority
+            )
+            if event:
+                self._global_events_account += 1
 
     def record_transaction(self, data):
         """Record a single transaction against this application."""

newrelic/core/stats_engine.py

@@ -34,7 +34,7 @@
 import newrelic.packages.six as six
 from newrelic.api.settings import STRIP_EXCEPTION_MESSAGE
 from newrelic.api.time_trace import get_linking_metadata
-from newrelic.common.encoding_utils import json_encode, safe_json_encode
+from newrelic.common.encoding_utils import json_encode
 from newrelic.common.metric_utils import create_metric_identity
 from newrelic.common.object_names import parse_exc_info
 from newrelic.common.streaming_utils import StreamBuffer
@@ -1232,18 +1232,56 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=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
 
-        message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
+            # Truncate the now unpacked and string converted message
+            message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
 
-        collected_attributes = get_linking_metadata()
-        if attributes and (settings and settings.application_logging.forwarding.context_data.enabled):
-            context_attributes = resolve_logging_context_attributes(attributes, settings.attribute_filter, "context.")
+        # 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:
-                collected_attributes.update(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
+
+        # 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,