Log Forwarding User Attributes (#682)

* Add context data setting Co-authored-by: Uma Annamalai <[email protected]> Co-authored-by: Hannah Stepanek <[email protected]> Co-authored-by: Lalleh Rafeei <[email protected]> * Update record_log_event signature with attributes * Logging attributes initial implementation * Fix settings attribute error * Update logging instrumentation with attributes * Update log handler API * Add loguru support for extra attrs * Add more explicit messaging to validator * Expanding testing for record_log_event * Expand record log event testing * Fix settings typo * Remove missing loguru attributes from test * Adjust safe log attr encoding * Correct py2 issues * Fix missing record attrs in logging. Co-authored-by: Uma Annamalai <[email protected]> Co-authored-by: Hannah Stepanek <[email protected]> Co-authored-by: Lalleh Rafeei <[email protected]> Co-authored-by: Hannah Stepanek <[email protected]>
newrelic · Dec 11, 2023 · 1d43944 · 1d43944
1 parent 030cfc9
commit 1d43944
Show file tree

Hide file tree

Showing 21 changed files with 396 additions and 122 deletions.
diff --git a/newrelic/api/application.py b/newrelic/api/application.py
@@ -162,9 +162,9 @@ 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:

diff --git a/newrelic/api/log.py b/newrelic/api/log.py
@@ -22,8 +22,10 @@
 from newrelic.api.transaction import current_transaction, record_log_event
 from newrelic.common import agent_http
 from newrelic.common.object_names import parse_exc_info
+from newrelic.common.encoding_utils import safe_json_encode
 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):
@@ -43,7 +45,7 @@ def format_exc_info(exc_info):
 
 
 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 +78,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 +92,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):
     """

diff --git a/newrelic/api/transaction.py b/newrelic/api/transaction.py
@@ -44,6 +44,7 @@
     json_decode,
     json_encode,
     obfuscate,
+    safe_json_encode,
     snake_case,
 )
 from newrelic.core.attribute 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
@@ -1544,11 +1545,16 @@ def record_log_event(self, message, level=None, timestamp=None, priority=None):
 
         message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
 
+        attrs = get_linking_metadata()
+        if attributes and (settings and settings.application_logging and settings.application_logging.forwarding and settings.application_logging.forwarding.context_data and settings.application_logging.forwarding.context_data.enabled):
+            # TODO add attibute filtering
+            attrs.update({"context." + k: safe_json_encode(v, ignore_string_types=True) for k, v in six.iteritems(attributes)})
+
         event = LogEventNode(
             timestamp=timestamp,
             level=level,
             message=message,
-            attributes=get_linking_metadata(),
+            attributes=attrs,
         )
 
         self._log_events.add(event, priority=priority)
@@ -2061,7 +2067,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:
@@ -2072,12 +2078,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, "
@@ -2088,7 +2094,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"):

diff --git a/newrelic/common/encoding_utils.py b/newrelic/common/encoding_utils.py
@@ -111,6 +111,29 @@ 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.
 

diff --git a/newrelic/config.py b/newrelic/config.py
@@ -552,6 +552,7 @@ def _process_configuration(section):
     _process_setting(section, "application_logging.enabled", "getboolean", None)
     _process_setting(section, "application_logging.forwarding.max_samples_stored", "getint", None)
     _process_setting(section, "application_logging.forwarding.enabled", "getboolean", None)
+    _process_setting(section, "application_logging.forwarding.context_data.enabled", "getboolean", None)
     _process_setting(section, "application_logging.metrics.enabled", "getboolean", None)
     _process_setting(section, "application_logging.local_decorating.enabled", "getboolean", None)
 

diff --git a/newrelic/core/agent.py b/newrelic/core/agent.py
@@ -565,12 +565,12 @@ def record_ml_event(self, app_name, event_type, params):
 
         application.record_ml_event(event_type, params)
 
-    def record_log_event(self, app_name, message, level=None, timestamp=None, priority=None):
+    def record_log_event(self, app_name, message, level=None, timestamp=None,  attributes=None, priority=None):
         application = self._applications.get(app_name, None)
         if application is None or not application.active:
             return
 
-        application.record_log_event(message, level, timestamp, priority=priority)
+        application.record_log_event(message, level, timestamp, attributes=attributes, priority=priority)
 
     def record_transaction(self, app_name, data):
         """Processes the raw transaction data, generating and recording

diff --git a/newrelic/core/application.py b/newrelic/core/application.py
@@ -939,13 +939,13 @@ def record_ml_event(self, event_type, params):
                 self._global_events_account += 1
                 self._stats_engine.record_ml_event(event)
 
-    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 not self._active_session:
             return
 
         if message:
             with self._stats_custom_lock:
-                event = self._stats_engine.record_log_event(message, level, timestamp, priority=priority)
+                event = self._stats_engine.record_log_event(message, level, timestamp, attributes=attributes, priority=priority)
                 if event:
                     self._global_events_account += 1
 

diff --git a/newrelic/core/config.py b/newrelic/core/config.py
@@ -301,6 +301,10 @@ class ApplicationLoggingForwardingSettings(Settings):
     pass
 
 
+class ApplicationLoggingForwardingContextDataSettings(Settings):
+    pass
+
+
 class ApplicationLoggingMetricsSettings(Settings):
     pass
 
@@ -398,6 +402,8 @@ class EventHarvestConfigHarvestLimitSettings(Settings):
 _settings.agent_limits = AgentLimitsSettings()
 _settings.application_logging = ApplicationLoggingSettings()
 _settings.application_logging.forwarding = ApplicationLoggingForwardingSettings()
+_settings.application_logging.forwarding.context_data = ApplicationLoggingForwardingContextDataSettings()
+_settings.application_logging.metrics = ApplicationLoggingMetricsSettings()
 _settings.application_logging.local_decorating = ApplicationLoggingLocalDecoratingSettings()
 _settings.application_logging.metrics = ApplicationLoggingMetricsSettings()
 _settings.machine_learning = MachineLearningSettings()
@@ -893,6 +899,9 @@ def default_otlp_host(host):
 _settings.application_logging.forwarding.enabled = _environ_as_bool(
     "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_ENABLED", default=True
 )
+_settings.application_logging.forwarding.context_data.enabled = _environ_as_bool(
+    "NEW_RELIC_APPLICATION_LOGGING_FORWARDING_CONTEXT_DATA_ENABLED", default=False
+)
 _settings.application_logging.metrics.enabled = _environ_as_bool(
     "NEW_RELIC_APPLICATION_LOGGING_METRICS_ENABLED", default=True
 )

diff --git a/newrelic/core/stats_engine.py b/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
+from newrelic.common.encoding_utils import json_encode, safe_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
@@ -1218,7 +1218,8 @@ def record_transaction(self, transaction):
         ):
             self._log_events.merge(transaction.log_events, priority=transaction.priority)
 
-    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
@@ -1238,11 +1239,16 @@ def record_log_event(self, message, level=None, timestamp=None, priority=None):
 
         message = truncate(message, MAX_LOG_MESSAGE_LENGTH)
 
+        attrs = get_linking_metadata()
+        if attributes and (settings and settings.application_logging and settings.application_logging.forwarding and settings.application_logging.forwarding.context_data and settings.application_logging.forwarding.context_data.enabled):
+            # TODO add attibute filtering
+            attrs.update({"context." + k: safe_json_encode(v, ignore_string_types=True) for k, v in six.iteritems(attributes)})
+
         event = LogEventNode(
             timestamp=timestamp,
             level=level,
             message=message,
-            attributes=get_linking_metadata(),
+            attributes=attrs, 
         )
 
         if priority is None:

diff --git a/newrelic/hooks/logger_logging.py b/newrelic/hooks/logger_logging.py
@@ -12,18 +12,24 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+from logging import Formatter, LogRecord
+
 from newrelic.api.application import application_instance
 from newrelic.api.time_trace import get_linking_metadata
 from newrelic.api.transaction import current_transaction, record_log_event
 from newrelic.common.object_wrapper import function_wrapper, wrap_function_wrapper
 from newrelic.core.config import global_settings
+from newrelic.packages import six
 
 try:
     from urllib import quote
 except ImportError:
     from urllib.parse import quote
 
 
+DEFAULT_LOG_RECORD_KEYS = frozenset(set(vars(LogRecord("", 0, "", 0, "", (), None))) | {"message"})
+
+
 def add_nr_linking_metadata(message):
     available_metadata = get_linking_metadata()
     entity_name = quote(available_metadata.get("entity.name", ""))
@@ -46,6 +52,15 @@ def bind_callHandlers(record):
     return record
 
 
+def filter_record_attributes(record):
+    record_attrs = vars(record)
+    custom_attr_keys = set(record_attrs.keys()) - DEFAULT_LOG_RECORD_KEYS
+    if custom_attr_keys:
+        return {k: record_attrs[k] for k in custom_attr_keys if k not in DEFAULT_LOG_RECORD_KEYS}
+    else:
+        return None
+
+
 def wrap_callHandlers(wrapped, instance, args, kwargs):
     transaction = current_transaction()
     record = bind_callHandlers(*args, **kwargs)
@@ -75,7 +90,8 @@ def wrap_callHandlers(wrapped, instance, args, kwargs):
         if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
             try:
                 message = record.getMessage()
-                record_log_event(message, level_name, int(record.created * 1000))
+                attrs = filter_record_attributes(record)
+                record_log_event(message=message, level=level_name, timestamp=int(record.created * 1000), attributes=attrs)
             except Exception:
                 pass
 

diff --git a/newrelic/hooks/logger_loguru.py b/newrelic/hooks/logger_loguru.py
@@ -59,8 +59,10 @@ def _nr_log_forwarder(message_instance):
                     application.record_custom_metric("Logging/lines/%s" % level_name, {"count": 1})
 
         if settings.application_logging.forwarding and settings.application_logging.forwarding.enabled:
+            attrs = dict(record.get("extra", {}))
+
             try:
-                record_log_event(message, level_name, int(record["time"].timestamp()))
+                record_log_event(message, level_name, int(record["time"].timestamp()), attributes=attrs)
             except Exception:
                 pass