Add attribute filtering for log events

newrelic/api/transaction.py

@@ -54,6 +54,7 @@
     create_agent_attributes,
     create_attributes,
     create_user_attributes,
+    resolve_logging_context_attributes,
     process_user_attribute,
     truncate,
 )
@@ -1545,16 +1546,17 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=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)})
+        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.")
+            if context_attributes:
+                collected_attributes.update(context_attributes)
 
         event = LogEventNode(
             timestamp=timestamp,
             level=level,
             message=message,
-            attributes=attrs,
+            attributes=collected_attributes,
         )
 
         self._log_events.add(event, priority=priority)

newrelic/core/attribute.py

@@ -18,6 +18,7 @@
 from newrelic.core.attribute_filter import (
     DST_ALL,
     DST_ERROR_COLLECTOR,
+    DST_LOG_EVENT_CONTEXT_DATA,
     DST_SPAN_EVENTS,
     DST_TRANSACTION_EVENTS,
     DST_TRANSACTION_SEGMENTS,
@@ -174,6 +175,35 @@ def resolve_agent_attributes(attr_dict, attribute_filter, target_destination, at
     return a_attrs
 
 
+def resolve_logging_context_attributes(attr_dict, attribute_filter, attr_prefix, attr_class=dict):
+    """
+    Helper function for processing logging context attributes that require a prefix. Correctly filters attribute names
+    before applying the required prefix, and then applies the process_user_attribute after the prefix is applied to
+    correctly check length requirements.
+    """
+    c_attrs = attr_class()
+
+    for attr_name, attr_value in attr_dict.items():
+        if attr_value is None:
+            continue
+
+        dest = attribute_filter.apply(attr_name, DST_LOG_EVENT_CONTEXT_DATA)
+
+        if dest & DST_LOG_EVENT_CONTEXT_DATA:
+            try:
+                attr_name, attr_value = process_user_attribute(attr_prefix + attr_name, attr_value)
+                if attr_name:
+                    c_attrs[attr_name] = attr_value
+            except Exception:
+                _logger.debug(
+                    "Log event context attribute failed to validate for unknown reason. Dropping context attribute: %s. Check traceback for clues.",
+                    attr_name,
+                    exc_info=True,
+                )
+
+    return c_attrs
+
+
 def create_user_attributes(attr_dict, attribute_filter):
     destinations = DST_ALL
     return create_attributes(attr_dict, destinations, attribute_filter)

newrelic/core/attribute_filter.py

@@ -15,13 +15,14 @@
 # Attribute "destinations" represented as bitfields.
 
 DST_NONE = 0x0
-DST_ALL  = 0x3F
+DST_ALL  = 0x7F
 DST_TRANSACTION_EVENTS   = 1 << 0
 DST_TRANSACTION_TRACER   = 1 << 1
 DST_ERROR_COLLECTOR      = 1 << 2
 DST_BROWSER_MONITORING   = 1 << 3
 DST_SPAN_EVENTS          = 1 << 4
 DST_TRANSACTION_SEGMENTS = 1 << 5
+DST_LOG_EVENT_CONTEXT_DATA = 1 << 6
 
 class AttributeFilter(object):
 
@@ -92,6 +93,9 @@ def _set_enabled_destinations(self, settings):
         if settings.get('browser_monitoring.attributes.enabled', None):
             enabled_destinations |= DST_BROWSER_MONITORING
 
+        if settings.get('application_logging.forwarding.context_data.enabled', None):
+            enabled_destinations |= DST_LOG_EVENT_CONTEXT_DATA
+
         if not settings.get('attributes.enabled', None):
             enabled_destinations = DST_NONE
 
@@ -121,6 +125,8 @@ def _build_rules(self, settings):
             ('span_events.attributes.exclude', DST_SPAN_EVENTS, False),
             ('transaction_segments.attributes.include', DST_TRANSACTION_SEGMENTS, True),
             ('transaction_segments.attributes.exclude', DST_TRANSACTION_SEGMENTS, False),
+            ('application_logging.forwarding.context_data.include', DST_LOG_EVENT_CONTEXT_DATA, True),
+            ('application_logging.forwarding.context_data.exclude', DST_LOG_EVENT_CONTEXT_DATA, False),
         )
 
         rules = []

newrelic/core/stats_engine.py

@@ -43,6 +43,7 @@
     create_agent_attributes,
     create_user_attributes,
     process_user_attribute,
+    resolve_logging_context_attributes,
     truncate,
 )
 from newrelic.core.attribute_filter import DST_ERROR_COLLECTOR
@@ -1239,16 +1240,17 @@ def record_log_event(self, message, level=None, timestamp=None, attributes=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)})
+        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.")
+            if context_attributes:
+                collected_attributes.update(context_attributes)
 
         event = LogEventNode(
             timestamp=timestamp,
             level=level,
             message=message,
-            attributes=attrs, 
+            attributes=collected_attributes, 
         )
 
         if priority is None:

tests/agent_features/test_log_events.py

@@ -12,9 +12,14 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import pytest
+
 from newrelic.api.background_task import background_task
 from newrelic.api.time_trace import current_trace
 from newrelic.api.transaction import current_transaction, record_log_event, ignore_transaction
+
+from newrelic.core.config import _parse_attributes
+
 from testing_support.fixtures import override_application_settings, reset_core_stats_engine
 from testing_support.validators.validate_log_event_count import validate_log_event_count
 from testing_support.validators.validate_log_event_count_outside_transaction import (
@@ -27,7 +32,7 @@
 class NonPrintableObject(object):
     def __str__(self):
         raise RuntimeError("Unable to print object.")
-    
+
     __repr__ = __str__
 
 
@@ -71,10 +76,11 @@ def exercise_record_log_event():
 enable_log_forwarding = override_application_settings(
     {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": True}
 )
+disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False})
+
 disable_log_attributes = override_application_settings(
     {"application_logging.forwarding.enabled": True, "application_logging.forwarding.context_data.enabled": False}
 )
-disable_log_forwarding = override_application_settings({"application_logging.forwarding.enabled": False})
 
 _common_attributes_service_linking = {
     "timestamp": None,
@@ -92,6 +98,9 @@ def exercise_record_log_event():
     "dict_attr": {"key": "value"},
     "non_serializable_attr": NonSerializableObject(),
     "non_printable_attr": NonPrintableObject(),
+    "attr_value_too_long": "*" * 256,
+    "attr_name_too_long_" + ("*" * 237): "value",
+    "attr_name_with_prefix_too_long_" + ("*" * 220): "value",
 }
 
 _exercise_record_log_event_events = [
@@ -102,10 +111,10 @@ def exercise_record_log_event():
         "message": "serialized_attributes",
         "context.str_attr": "Value",
         "context.bytes_attr": b"value",
-        "context.int_attr": "1",
-        "context.dict_attr": '{"key":"value"}',
+        "context.int_attr": 1,
+        "context.dict_attr": "{'key': 'value'}",
         "context.non_serializable_attr": "<NonSerializableObject object>",
-        "context.non_printable_attr": "<unprintable NonPrintableObject object>",
+        "context.attr_value_too_long": "*" * 255,
     },
 ]
 _exercise_record_log_event_inside_transaction_events = [
@@ -114,12 +123,17 @@ def exercise_record_log_event():
 _exercise_record_log_event_outside_transaction_events = [
     combine_dicts(_common_attributes_service_linking, log) for log in _exercise_record_log_event_events
 ]
+_exercise_record_log_event_forgone_attrs = [
+    "context.non_printable_attr", "attr_name_too_long_", "attr_name_with_prefix_too_long_"
+]
+
 
 # Test Log Forwarding
 
+
 @enable_log_forwarding
 def test_record_log_event_inside_transaction():
-    @validate_log_events(_exercise_record_log_event_inside_transaction_events)
+    @validate_log_events(_exercise_record_log_event_inside_transaction_events, forgone_attrs=_exercise_record_log_event_forgone_attrs)
     @validate_log_event_count(len(_exercise_record_log_event_inside_transaction_events))
     @background_task()
     def test():
@@ -131,7 +145,7 @@ def test():
 @enable_log_forwarding
 @reset_core_stats_engine()
 def test_record_log_event_outside_transaction():
-    @validate_log_events_outside_transaction(_exercise_record_log_event_outside_transaction_events)
+    @validate_log_events_outside_transaction(_exercise_record_log_event_outside_transaction_events, forgone_attrs=_exercise_record_log_event_forgone_attrs)
     @validate_log_event_count_outside_transaction(len(_exercise_record_log_event_outside_transaction_events))
     def test():
         exercise_record_log_event()
@@ -154,6 +168,7 @@ def test():
 
 _test_log_event_truncation_events = [{"message": "A" * 32768}]
 
+
 @enable_log_forwarding
 def test_log_event_truncation_inside_transaction():
     @validate_log_events(_test_log_event_truncation_events)
@@ -178,6 +193,7 @@ def test():
 
 # Test Log Forwarding Settings
 
+
 @disable_log_forwarding
 def test_disabled_record_log_event_inside_transaction():
     @validate_log_event_count(0)
@@ -197,8 +213,10 @@ def test():
 
     test()
 
+
 # Test Log Attribute Settings
 
+
 @disable_log_attributes
 def test_attributes_disabled_inside_transaction():
     @validate_log_events([{"message": "A"}], forgone_attrs=["context.key"])
@@ -219,3 +237,86 @@ def test():
         record_log_event("A", attributes={"key": "value"})
 
     test()
+
+
+_test_record_log_event_attribute_filtering_params = [
+    ("", "", "context.A", True),
+    ("", "A", "context.A", False),
+    ("", "A", "context.B", True),
+    ("A B", "*", "context.A", True),
+    ("A B", "*", "context.B", True),
+    ("A B", "*", "context.C", False),
+    ("A B", "C" , "context.A", True),
+    ("A B", "C" , "context.C", False),
+    ("A B", "B" , "context.A", True),
+    ("A B", "B" , "context.B", False),
+    ("A", "A *" , "context.A", False),
+    ("A", "A *" , "context.B", False),
+    ("A*", "" , "context.A", True),
+    ("A*", "" , "context.AB", True),
+    ("", "A*" , "context.A", False),
+    ("", "A*" , "context.B", True),
+    ("A*", "AB" , "context.AC", True),
+    ("A*", "AB" , "context.AB", False),
+    ("AB", "A*" , "context.AB", True),
+    ("A*", "AB*" , "context.ACB", True),
+    ("A*", "AB*" , "context.ABC", False),
+    # Linking attributes not affected by filtering
+    ("", "", "entity.name", True),
+    ("A", "*", "entity.name", True),
+    ("", "*", "entity.name", True),
+]
+
+
+@pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_attribute_filtering_params)
+def test_record_log_event_attribute_filtering_inside_transaction(include, exclude, attr, expected):
+    if expected:
+        expected_event = {"required_attrs": [attr]}
+    else:
+        expected_event = {"forgone_attrs": [attr]}
+
+    @override_application_settings(
+        {
+            "application_logging.forwarding.enabled": True,
+            "application_logging.forwarding.context_data.enabled": True,
+            "application_logging.forwarding.context_data.include": _parse_attributes(include),
+            "application_logging.forwarding.context_data.exclude": _parse_attributes(exclude),
+        }
+    )
+    @validate_log_events(**expected_event)
+    @validate_log_event_count(1)
+    @background_task()
+    def test():
+        if attr.startswith("context."):
+            record_log_event("A", attributes={attr.lstrip("context."): 1})
+        else:
+            record_log_event("A")
+
+    test()
+
+
+@pytest.mark.parametrize("include,exclude,attr,expected", _test_record_log_event_attribute_filtering_params)
+@reset_core_stats_engine()
+def test_record_log_event_attribute_filtering_outside_transaction(include, exclude, attr, expected):
+    if expected:
+        expected_event = {"required_attrs": [attr]}
+    else:
+        expected_event = {"forgone_attrs": [attr]}
+
+    @override_application_settings(
+        {
+            "application_logging.forwarding.enabled": True,
+            "application_logging.forwarding.context_data.enabled": True,
+            "application_logging.forwarding.context_data.include": _parse_attributes(include),
+            "application_logging.forwarding.context_data.exclude": _parse_attributes(exclude),
+        }
+    )
+    @validate_log_events_outside_transaction(**expected_event)
+    @validate_log_event_count_outside_transaction(1)
+    def test():
+        if attr.startswith("context."):
+            record_log_event("A", attributes={attr.lstrip("context."): 1})
+        else:
+            record_log_event("A")
+
+    test()

tests/testing_support/validators/validate_log_events_outside_transaction.py

@@ -20,8 +20,9 @@
 from newrelic.packages import six
 
 
-def validate_log_events_outside_transaction(events=None, forgone_attrs=None):
+def validate_log_events_outside_transaction(events=None, required_attrs=None, forgone_attrs=None):
     events = events or [{}]  # Empty event allows assertions based on only forgone attrs to still run and validate
+    required_attrs = required_attrs or []
     forgone_attrs = forgone_attrs or []
 
     @function_wrapper
@@ -55,14 +56,14 @@ def _validate_log_events_outside_transaction(wrapped, instance, args, kwargs):
             matching_log_events = 0
             mismatches = []
             for captured in logs:
-                if _check_log_attributes(expected, forgone_attrs, captured, mismatches):
+                if _check_log_attributes(expected, required_attrs, forgone_attrs, captured, mismatches):
                     matching_log_events += 1
             assert matching_log_events == 1, _log_details(matching_log_events, logs, mismatches)
 
         return val
 
 
-    def _check_log_attributes(expected, forgone_attrs, captured, mismatches):
+    def _check_log_attributes(expected, required_attrs, forgone_attrs, captured, mismatches):
         for key, value in six.iteritems(expected):
             if hasattr(captured, key):
                 captured_value = getattr(captured, key, None)
@@ -77,6 +78,11 @@ def _check_log_attributes(expected, forgone_attrs, captured, mismatches):
                     mismatches.append("key: %s, value:<%s><%s>" % (key, value, captured_value))
                     return False
 
+        for key in required_attrs:
+            if not hasattr(captured, key) and key not in captured.attributes:
+                mismatches.append("required_key: %s" % key)
+                return False
+
         for key in forgone_attrs:
             if hasattr(captured, key):
                 mismatches.append("forgone_key: %s, value:<%s>" % (key, getattr(captured, key, None)))